diff --git a/docs/environment/timeouts.md b/docs/environment/timeouts.md index 41f43ec6e..c5566028d 100644 --- a/docs/environment/timeouts.md +++ b/docs/environment/timeouts.md @@ -5,41 +5,44 @@ introduction: Configure and handle timeouts. --- When a Lambda function times out, it is like the power to the computer is suddenly -just turned off. This does not give the application a chance to shutdown properly. -This often leaves you without any logs and the problem could be hard to fix. +just turned off. This does not give the application a chance to shut down properly. +This leaves you without any logs and the problem could be hard to fix. -> Note, this feature is experimental in Bref 1.3 and you need top opt-in by defining `BREF_TIMEOUT=0`. +To allow your application to shut down properly and write logs, Bref can throw an exception just before the Lambda times out. -Bref will throw an `LambdaTimeout` exception just before the Lambda actually times -out. This will allow your application to actually shutdown. +> Note, this feature is experimental and available since Bref 1.3. -This feature is enabled automatically for the `php-xx` layer and the `console` layer. -The `php-xx-fpm` layer needs to opt-in by adding the following to `index.php`. +To enable this feature **in `php-XX` layers**, set the environment variable `BREF_FEATURE_TIMEOUT`: + +```yaml +provider: + environment: + BREF_FEATURE_TIMEOUT: 1 +``` + +To enable this feature **in `php-XX-fpm` layers**, call `Timeout::enableInFpm()` in your application. +For example in `index.php`: ```php if (isset($_SERVER['LAMBDA_TASK_ROOT'])) { - \Bref\Timeout\Timeout::enable(); + \Bref\Timeout\Timeout::enableInFpm(); } ``` -## Configuration +Whenever a timeout happens, a full stack trace will be logged, including the line that was executing. -You may configure this behavior with the `BREF_TIMEOUT` environment variable. To -always trigger an exception after 10 seconds, set `BREF_TIMEOUT=10`. To disable -Bref throwing an exception use value `BREF_TIMEOUT=-1`. To automatically set the -timeout just a hair shorter than the Lambda timeout, use `BREF_TIMEOUT=0`. +In most cases, it is an external call to a database, cache or API that is stuck waiting. +If you are using a RDS database, [you are encouraged to read this section](database.md#accessing-the-internet). ## Catching the exception -If you are using a framework, then the framework is probably catching all exceptions -and displays an error page for the users. You may of course catch the exception -yourself: +You can catch the timeout exception to perform some cleanup, logs or even display a proper error page. -```php -generateResponse(); + // your code here + // ... } catch (LambdaTimeout $e) { echo 'Oops, sorry. We spent too much time on this.'; } catch (\Throwable $e) { - echo 'Some unexpected error happened.'; + echo 'Some other unexpected error happened.'; } } - - private function generateResponse() - { - $pi = // ... - echo 'Pi is '.$pi; - } } - -return new Handler(); ``` - -## Debugging timeouts - -The exception stacktrace will show you which line that was executing when the -exception was thrown. This could be helpful when trying to figure out why the -application took more time than expected. - -In the vast majority of cases, it is an external call to a database, cache or API -that is stuck waiting for IO. diff --git a/runtime/layers/fpm/bootstrap b/runtime/layers/fpm/bootstrap index 1142fc880..36647b074 100755 --- a/runtime/layers/fpm/bootstrap +++ b/runtime/layers/fpm/bootstrap @@ -7,6 +7,15 @@ use Bref\Runtime\LambdaRuntime; ini_set('display_errors', '1'); error_reporting(E_ALL); +/** + * Disable the Bref timeout feature in the main bootstrap process. + * Indeed it doesn't make sense here because the application code runs in the + * FPM worker process, not in this process (the bootstrap process). We don't want to + * terminate the bootstrap process while leaving the FPM worker running. + * That's why we force `BREF_FEATURE_TIMEOUT` to be disabled. + */ +putenv('BREF_FEATURE_TIMEOUT=0'); + $appRoot = getenv('LAMBDA_TASK_ROOT'); if (getenv('BREF_DOWNLOAD_VENDOR')) { @@ -25,8 +34,7 @@ if (getenv('BREF_DOWNLOAD_VENDOR')) { require $appRoot . '/vendor/autoload.php'; } -// Get a LambdaRuntime and disable timeout exceptions. -$lambdaRuntime = LambdaRuntime::fromEnvironmentVariable(-1); +$lambdaRuntime = LambdaRuntime::fromEnvironmentVariable(); $handlerFile = $appRoot . '/' . getenv('_HANDLER'); if (! is_file($handlerFile)) { diff --git a/src/Runtime/LambdaRuntime.php b/src/Runtime/LambdaRuntime.php index e20e19f6f..f155af176 100755 --- a/src/Runtime/LambdaRuntime.php +++ b/src/Runtime/LambdaRuntime.php @@ -43,30 +43,15 @@ final class LambdaRuntime /** @var Invoker */ private $invoker; - /** @var int seconds */ - private $timeout; + /** @var bool */ + private $enableTimeout; - public static function fromEnvironmentVariable(?int $timeout = null): self + public static function fromEnvironmentVariable(): self { - if ($timeout === null) { - $envTimeout = getenv('BREF_TIMEOUT'); - if ($envTimeout === false || $envTimeout === '') { - // In 1.3 the Timeout exception is opt-in only - $timeout = -1; - } else { - $timeout = (int) $envTimeout; - } - } - - return new self((string) getenv('AWS_LAMBDA_RUNTIME_API'), $timeout); + return new self((string) getenv('AWS_LAMBDA_RUNTIME_API'), (bool) getenv('BREF_FEATURE_TIMEOUT')); } - /** - * @param int $timeout number of seconds before a TimeoutException is thrown. - * Value -1 means "disabled". Value 0 means "auto", this will - * set the timeout just a bit shorter than the Lambda timeout. - */ - public function __construct(string $apiUrl, int $timeout = 0) + private function __construct(string $apiUrl, bool $enableTimeout) { if ($apiUrl === '') { die('At the moment lambdas can only be executed in an Lambda environment'); @@ -74,7 +59,7 @@ public function __construct(string $apiUrl, int $timeout = 0) $this->apiUrl = $apiUrl; $this->invoker = new Invoker; - $this->timeout = $timeout; + $this->enableTimeout = $enableTimeout; } public function __destruct() @@ -116,11 +101,10 @@ public function processNextEvent($handler): void [$event, $context] = $this->waitNextInvocation(); \assert($context instanceof Context); - if ($this->timeout > 0) { - Timeout::timeoutAfter($this->timeout); - } elseif ($this->timeout === 0 && 0 < $context->getRemainingTimeInMillis()) { + $remainingTimeInMillis = $context->getRemainingTimeInMillis(); + if ($this->enableTimeout && 0 < $remainingTimeInMillis) { // Throw exception one second before Lambda pulls the plug. - Timeout::timeoutAfter(max(1, (int) floor($context->getRemainingTimeInMillis() / 1000) - 1)); + Timeout::enable($context->getRemainingTimeInMillis()); } $this->ping(); diff --git a/src/Timeout/Timeout.php b/src/Timeout/Timeout.php index c326dcd37..55091abde 100644 --- a/src/Timeout/Timeout.php +++ b/src/Timeout/Timeout.php @@ -3,7 +3,7 @@ namespace Bref\Timeout; /** - * Helper class to trigger an exception just before the Lamba times out. This + * Helper class to trigger an exception just before the Lambda times out. This * will give the application a chance to shut down. */ final class Timeout @@ -12,40 +12,44 @@ final class Timeout private static $initialized = false; /** - * Read environment variables and setup timeout exception. + * Automatically setup a timeout (based on the AWS Lambda timeout). + * + * This method can only be called when running in PHP-FPM, i.e. when using a `php-XX-fpm` layer. */ - public static function enable(): void + public static function enableInFpm(): void { - if (isset($_SERVER['BREF_TIMEOUT'])) { - $timeout = (int) $_SERVER['BREF_TIMEOUT']; - if ($timeout === -1) { - return; - } + if (! isset($_SERVER['LAMBDA_INVOCATION_CONTEXT'])) { + throw new \LogicException('Could not find value for bref timeout. Are we running on Lambda?'); + } - if ($timeout > 0) { - self::timeoutAfter($timeout); + $context = json_decode($_SERVER['LAMBDA_INVOCATION_CONTEXT'], true, 512, JSON_THROW_ON_ERROR); + $deadlineMs = $context['deadlineMs']; + $remainingTimeInMillis = $deadlineMs - intval(microtime(true) * 1000); - return; - } + self::enable($remainingTimeInMillis); + } - // else if 0, continue - } + /** + * @internal + */ + public static function enable(int $remainingTimeInMillis): void + { + self::init(); - if (isset($_SERVER['LAMBDA_INVOCATION_CONTEXT'])) { - $context = json_decode($_SERVER['LAMBDA_INVOCATION_CONTEXT'], true, 512, JSON_THROW_ON_ERROR); - $deadlineMs = $context['deadlineMs']; - $remainingTime = $deadlineMs - intval(microtime(true) * 1000); + $remainingTimeInSeconds = (int) floor($remainingTimeInMillis / 1000); - self::timeoutAfter(max(1, (int) floor($remainingTime / 1000) - 1)); + // The script will timeout 1 second before the remaining time + // to allow some time for Bref/our app to recover and cleanup + $margin = 1; - return; - } + $timeoutDelayInSeconds = max(1, $remainingTimeInSeconds - $margin); - throw new \LogicException('Could not find value for bref timeout. Are we running on Lambda?'); + // Trigger SIGALRM in X seconds + pcntl_alarm($timeoutDelayInSeconds); } /** - * Setup custom handler for SIGTERM. + * Setup custom handler for SIGALRM. */ private static function init(): void { @@ -59,6 +63,8 @@ private static function init(): void } pcntl_async_signals(true); + // Setup a handler for SIGALRM that throws an exception + // This will interrupt any running PHP code, including `sleep()` or code stuck waiting for I/O. pcntl_signal(SIGALRM, function (): void { throw new LambdaTimeout('Maximum AWS Lambda execution time reached'); }); @@ -66,17 +72,10 @@ private static function init(): void self::$initialized = true; } - /** - * Set a timer to throw an exception. - */ - public static function timeoutAfter(int $seconds): void - { - self::init(); - pcntl_alarm($seconds); - } - /** * Reset timeout. + * + * @internal */ public static function reset(): void { diff --git a/tests/Runtime/LambdaRuntimeTest.php b/tests/Runtime/LambdaRuntimeTest.php index 4dfa2cd2c..f6b6159ef 100644 --- a/tests/Runtime/LambdaRuntimeTest.php +++ b/tests/Runtime/LambdaRuntimeTest.php @@ -15,6 +15,7 @@ use Bref\Event\Sqs\SqsHandler; use Bref\Runtime\LambdaRuntime; use Bref\Test\Server; +use Bref\Timeout\LambdaTimeout; use GuzzleHttp\Psr7\Response; use PHPUnit\Framework\TestCase; use Psr\Http\Message\ResponseInterface; @@ -35,41 +36,40 @@ protected function setUp(): void { ob_start(); Server::start(); - $this->runtime = new LambdaRuntime('localhost:8126', -1); + // Mock the API with our test server + putenv('AWS_LAMBDA_RUNTIME_API=localhost:8126'); + $this->runtime = LambdaRuntime::fromEnvironmentVariable(); } protected function tearDown(): void { Server::stop(); ob_end_clean(); + // Cleanup + putenv('AWS_LAMBDA_RUNTIME_API='); + putenv('BREF_FEATURE_TIMEOUT='); } - public function testFromEnvironmentVariable() + public function test Lambda timeouts can be anticipated() { - $getTimeout = function ($runtime) { - $reflectionProp = (new \ReflectionObject($runtime))->getProperty('timeout'); - $reflectionProp->setAccessible(true); + // Re-create the runtime class with timeout prevention enabled + putenv('BREF_FEATURE_TIMEOUT=1'); + $this->runtime = LambdaRuntime::fromEnvironmentVariable(); - return $reflectionProp->getValue($runtime); - }; - - putenv('AWS_LAMBDA_RUNTIME_API=foo'); - putenv('BREF_TIMEOUT'); // unset + $this->givenAnEvent([]); - // In 1.3 this feature is opt-in only. - $this->assertEquals(-1, $getTimeout(LambdaRuntime::fromEnvironmentVariable())); + $start = microtime(true); + $this->runtime->processNextEvent(function () { + // This 10s sleep should be interrupted + sleep(10); + }); - // Enable this test when we want to enable the Timeout exception for all users - //$this->assertEquals(0, $getTimeout(LambdaRuntime::fromEnvironmentVariable())); - $this->assertEquals(-1, $getTimeout(LambdaRuntime::fromEnvironmentVariable(-1))); - $this->assertEquals(0, $getTimeout(LambdaRuntime::fromEnvironmentVariable(0))); - $this->assertEquals(10, $getTimeout(LambdaRuntime::fromEnvironmentVariable(10))); + $elapsedTime = microtime(true) - $start; + // The Lambda timeout was 2 seconds, we expect the Bref timeout to trigger 1 second before that: 1 second + $this->assertEqualsWithDelta(1, $elapsedTime, 0.2); - putenv('BREF_TIMEOUT=5'); - $this->assertEquals(5, $getTimeout(LambdaRuntime::fromEnvironmentVariable())); - $this->assertEquals(-1, $getTimeout(LambdaRuntime::fromEnvironmentVariable(-1))); - $this->assertEquals(0, $getTimeout(LambdaRuntime::fromEnvironmentVariable(0))); - $this->assertEquals(10, $getTimeout(LambdaRuntime::fromEnvironmentVariable(10))); + $this->assertInvocationErrorResult(LambdaTimeout::class, 'Maximum AWS Lambda execution time reached'); + $this->assertErrorInLogs(LambdaTimeout::class, 'Maximum AWS Lambda execution time reached'); } public function test basic behavior() @@ -376,6 +376,8 @@ private function givenAnEvent($event): void [ 'lambda-runtime-aws-request-id' => '1', 'lambda-runtime-invoked-function-arn' => 'test-function-name', + // now + 2 seconds + 'lambda-runtime-deadline-ms' => intval((microtime(true) + 2) * 1000), ], json_encode($event) ), diff --git a/tests/Server.php b/tests/Server.php index 1ecc7b6d6..87b17d575 100644 --- a/tests/Server.php +++ b/tests/Server.php @@ -140,6 +140,13 @@ public static function stop() if (self::$started) { self::getClient()->request('DELETE', 'guzzle-server'); } + $tries = 0; + while (self::isListening() && ++$tries < 5) { + usleep(100000); + } + if (self::isListening()) { + throw new \RuntimeException('Unable to stop node.js server'); + } self::$started = false; } @@ -159,11 +166,12 @@ public static function start() if (self::$started) { return; } - if (! self::isListening()) { - exec('node ' . __DIR__ . '/server.js ' - . self::$port . ' >> /tmp/server.log 2>&1 &'); - self::wait(); + if (self::isListening()) { + throw new \Exception('Server is already running'); } + exec('node ' . __DIR__ . '/server.js ' + . self::$port . ' >> /tmp/server.log 2>&1 &'); + self::wait(); self::$started = true; } diff --git a/tests/Timeout/TimeoutTest.php b/tests/Timeout/TimeoutTest.php index 9f408257a..7a000cc8d 100644 --- a/tests/Timeout/TimeoutTest.php +++ b/tests/Timeout/TimeoutTest.php @@ -1,6 +1,6 @@ expectException(\LogicException::class); - Timeout::enable(); - } - - public function testEnableWithBrefTimeoutInactive() - { - $_SERVER['BREF_TIMEOUT'] = -1; - $_SERVER['LAMBDA_INVOCATION_CONTEXT'] = json_encode(['deadlineMs' => (time() + 30) * 1000]); - - Timeout::enable(); + Timeout::enable(3000); $timeout = pcntl_alarm(0); - $this->assertSame(0, $timeout, 'Timeout should not be active when BREF_TIMEOUT=-1'); + // 2 seconds (1 second shorter than the 3s remaining time) + $this->assertSame(2, $timeout); } - public function testEnableWithBrefTimeout() + public function test enable in FPM() { - $_SERVER['BREF_TIMEOUT'] = 10; - - Timeout::enable(); - $timeout = pcntl_alarm(0); - $this->assertSame(10, $timeout, 'BREF_TIMEOUT=10 should have effect'); - } - - public function testEnableWithBrefTimeoutAndContext() - { - $_SERVER['BREF_TIMEOUT'] = 10; $_SERVER['LAMBDA_INVOCATION_CONTEXT'] = json_encode(['deadlineMs' => (time() + 30) * 1000]); - Timeout::enable(); + Timeout::enableInFpm(); $timeout = pcntl_alarm(0); - $this->assertSame(10, $timeout, 'BREF_TIMEOUT=10 should have effect over context'); - } - - public function testEnableWithBrefTimeoutZeroAndContext() - { - $_SERVER['BREF_TIMEOUT'] = 0; - $_SERVER['LAMBDA_INVOCATION_CONTEXT'] = json_encode(['deadlineMs' => (time() + 30) * 1000]); - - Timeout::enable(); - $timeout = pcntl_alarm(0); - $this->assertEqualsWithDelta(29, $timeout, 1, 'BREF_TIMEOUT=0 should fallback to context'); + $this->assertEqualsWithDelta(29, $timeout, 1); } - public function testEnableWithContext() + public function test enable in FPM requires the context() { - $_SERVER['LAMBDA_INVOCATION_CONTEXT'] = json_encode(['deadlineMs' => (time() + 30) * 1000]); - - Timeout::enable(); - $timeout = pcntl_alarm(0); - $this->assertEqualsWithDelta(29, $timeout, 1); + $this->expectException(\LogicException::class); + Timeout::enableInFpm(); } - public function testTimeoutAfter() + public function test timeouts are interrupted in time() { $start = microtime(true); - Timeout::timeoutAfter(2); + Timeout::enable(2000); try { sleep(4); $this->fail('We expect a LambdaTimeout before we reach this line'); } catch (LambdaTimeout $e) { $time = 1000 * (microtime(true) - $start); - $this->assertEqualsWithDelta(2000, $time, 200, 'We must wait about 2 seconds'); + $this->assertEqualsWithDelta(1000, $time, 200, 'We must wait about 1 second'); } catch (\Throwable $e) { $this->fail('It must throw a LambdaTimeout.'); } diff --git a/website/package-lock.json b/website/package-lock.json index d12b099da..1613cbb67 100644 --- a/website/package-lock.json +++ b/website/package-lock.json @@ -445,7 +445,6 @@ "integrity": "sha512-5dgndWOriYSm5cnYaJNhalLNDKOqFwyDB/rr1E9ZsGciGvKPs8R2xYGCacuf3z6K1YKDz182fd+fY3cn3pMqXQ==", "dev": true, "dependencies": { - "graceful-fs": "^4.1.6", "universalify": "^2.0.0" }, "optionalDependencies": {