From e78d2c6182713fee95e363a84e857d60b7be88ae Mon Sep 17 00:00:00 2001 From: Nyholm Date: Thu, 25 Mar 2021 15:12:24 +0100 Subject: [PATCH 1/9] Handle timeouts more gracefully by throwing exception near the hard end --- runtime/layers/fpm/bootstrap | 3 +- src/Runtime/LambdaRuntime.php | 30 ++++++++- src/Timeout/LambdaTimeout.php | 12 ++++ src/Timeout/Timeout.php | 92 +++++++++++++++++++++++++++ tests/Runtime/LambdaRuntimeTest.php | 25 +++++++- tests/Timeout/TimeoutTest.php | 99 +++++++++++++++++++++++++++++ 6 files changed, 256 insertions(+), 5 deletions(-) create mode 100644 src/Timeout/LambdaTimeout.php create mode 100644 src/Timeout/Timeout.php create mode 100644 tests/Timeout/TimeoutTest.php diff --git a/runtime/layers/fpm/bootstrap b/runtime/layers/fpm/bootstrap index 3b9bdf4f1..1142fc880 100755 --- a/runtime/layers/fpm/bootstrap +++ b/runtime/layers/fpm/bootstrap @@ -25,7 +25,8 @@ if (getenv('BREF_DOWNLOAD_VENDOR')) { require $appRoot . '/vendor/autoload.php'; } -$lambdaRuntime = LambdaRuntime::fromEnvironmentVariable(); +// Get a LambdaRuntime and disable timeout exceptions. +$lambdaRuntime = LambdaRuntime::fromEnvironmentVariable(-1); $handlerFile = $appRoot . '/' . getenv('_HANDLER'); if (! is_file($handlerFile)) { diff --git a/src/Runtime/LambdaRuntime.php b/src/Runtime/LambdaRuntime.php index a295e449d..43fe73030 100755 --- a/src/Runtime/LambdaRuntime.php +++ b/src/Runtime/LambdaRuntime.php @@ -5,6 +5,7 @@ use Bref\Context\Context; use Bref\Context\ContextBuilder; use Bref\Event\Handler; +use Bref\Timeout\Timeout; use Exception; use Psr\Http\Server\RequestHandlerInterface; @@ -42,12 +43,20 @@ final class LambdaRuntime /** @var Invoker */ private $invoker; - public static function fromEnvironmentVariable(): self + /** @var int seconds */ + private $timeout; + + public static function fromEnvironmentVariable(?int $timeout = null): self { - return new self((string) getenv('AWS_LAMBDA_RUNTIME_API')); + return new self((string) getenv('AWS_LAMBDA_RUNTIME_API'), $timeout ?? (int) getenv('BREF_TIMEOUT')); } - public function __construct(string $apiUrl) + /** + * @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) { if ($apiUrl === '') { die('At the moment lambdas can only be executed in an Lambda environment'); @@ -55,6 +64,12 @@ public function __construct(string $apiUrl) $this->apiUrl = $apiUrl; $this->invoker = new Invoker; + $this->timeout = $timeout; + + if ($timeout >= 0 && ! Timeout::init()) { + // If we fail to initialize + $this->timeout = -1; + } } public function __destruct() @@ -96,6 +111,13 @@ 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()) { + // Throw exception one second before Lambda pulls the plug. + Timeout::timeoutAfter(max(1, (int) floor($context->getRemainingTimeInMillis() / 1000) - 1)); + } + $this->ping(); try { @@ -104,6 +126,8 @@ public function processNextEvent($handler): void $this->sendResponse($context->getAwsRequestId(), $result); } catch (\Throwable $e) { $this->signalFailure($context->getAwsRequestId(), $e); + } finally { + Timeout::reset(); } } diff --git a/src/Timeout/LambdaTimeout.php b/src/Timeout/LambdaTimeout.php new file mode 100644 index 000000000..d46a0f3c2 --- /dev/null +++ b/src/Timeout/LambdaTimeout.php @@ -0,0 +1,12 @@ + 0) { + self::timeoutAfter($timeout); + + return; + } + + // else if 0, continue + } + + 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); + + self::timeoutAfter((int) floor($remainingTime / 1000)); + + return; + } + + throw new \LogicException('Could not find value for bref timeout. Are we running on Lambda?'); + } + + /** + * Setup custom handler for SIGTERM. One need to call Timeout::timoutAfter() + * to make an exception to be thrown. + * + * @return bool true if successful. + */ + public static function init(): bool + { + if (self::$initialized) { + return true; + } + + if (! function_exists('pcntl_async_signals')) { + trigger_error('Could not enable timeout exceptions because pcntl extension is not enabled.'); + return false; + } + + pcntl_async_signals(true); + pcntl_signal(SIGALRM, function (): void { + throw new LambdaTimeout('Maximum AWS Lambda execution time reached'); + }); + + self::$initialized = true; + + return true; + } + + /** + * Set a timer to throw an exception. + */ + public static function timeoutAfter(int $seconds): void + { + self::init(); + pcntl_alarm($seconds); + } + + /** + * Reset timeout. + */ + public static function reset(): void + { + if (self::$initialized) { + pcntl_alarm(0); + } + } +} diff --git a/tests/Runtime/LambdaRuntimeTest.php b/tests/Runtime/LambdaRuntimeTest.php index f72f0a56d..df4faad3b 100644 --- a/tests/Runtime/LambdaRuntimeTest.php +++ b/tests/Runtime/LambdaRuntimeTest.php @@ -35,7 +35,7 @@ protected function setUp(): void { ob_start(); Server::start(); - $this->runtime = new LambdaRuntime('localhost:8126'); + $this->runtime = new LambdaRuntime('localhost:8126', -1); } protected function tearDown(): void @@ -44,6 +44,29 @@ protected function tearDown(): void ob_end_clean(); } + public function testFromEnvironmentVariable() + { + $getTimeout = function ($runtime) { + $reflectionProp = (new \ReflectionObject($runtime))->getProperty('timeout'); + $reflectionProp->setAccessible(true); + + return $reflectionProp->getValue($runtime); + }; + + putenv('AWS_LAMBDA_RUNTIME_API=foo'); + putenv('BREF_TIMEOUT'); // unset + $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))); + + 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))); + } + public function test basic behavior() { $this->givenAnEvent(['Hello' => 'world!']); diff --git a/tests/Timeout/TimeoutTest.php b/tests/Timeout/TimeoutTest.php new file mode 100644 index 000000000..c1138fb84 --- /dev/null +++ b/tests/Timeout/TimeoutTest.php @@ -0,0 +1,99 @@ +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 = pcntl_alarm(0); + $this->assertSame(0, $timeout, 'Timeout should not be active when BREF_TIMEOUT=-1'); + } + + public function testEnableWithBrefTimeout() + { + $_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 = 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(30, $timeout, 1, 'BREF_TIMEOUT=0 should fallback to context'); + } + + public function testEnableWithContext() + { + $_SERVER['LAMBDA_INVOCATION_CONTEXT'] = json_encode(['deadlineMs' => (time() + 30) * 1000]); + + Timeout::enable(); + $timeout = pcntl_alarm(0); + $this->assertEqualsWithDelta(30, $timeout, 1); + } + + public function testTimeoutAfter() + { + $start = microtime(true); + Timeout::timeoutAfter(2); + 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'); + } catch (\Throwable $e) { + $this->fail('It must throw a LambdaTimeout.'); + } + } +} From 5a57044b5f0fa2191c36c01a26d9dcfc703be43d Mon Sep 17 00:00:00 2001 From: Nyholm Date: Fri, 26 Mar 2021 10:37:04 +0100 Subject: [PATCH 2/9] Added documentation for Timeouts --- couscous.yml | 4 +++ docs/environment/database.md | 2 ++ docs/environment/timeouts.md | 65 ++++++++++++++++++++++++++++++++++++ 3 files changed, 71 insertions(+) create mode 100644 docs/environment/timeouts.md diff --git a/couscous.yml b/couscous.yml index 46da09db7..f9fe88622 100644 --- a/couscous.yml +++ b/couscous.yml @@ -114,6 +114,10 @@ menu: text: Databases url: /docs/environment/database.html title: Using a database from AWS Lambda + timeouts: + text: Timeouts + url: /docs/environment/timeouts.html + title: Configure and handle timeouts custom-domains: text: Custom domains url: /docs/environment/custom-domains.html diff --git a/docs/environment/database.md b/docs/environment/database.md index 631a5cb25..476827999 100644 --- a/docs/environment/database.md +++ b/docs/environment/database.md @@ -54,6 +54,8 @@ When possible, an alternative to NAT Gateways is to split the work done by a lam Finally, another free alternative to NAT Gateway is to access AWS services by creating "*private VPC endpoints*": this is possible for S3, API Gateway, [and more](https://docs.aws.amazon.com/en_pv/vpc/latest/userguide/vpc-endpoints-access.html). +Read more in the section about [timeouts](/docs/environment/timeouts.md). + ## Creating a database On the [RDS console](https://console.aws.amazon.com/rds/home): diff --git a/docs/environment/timeouts.md b/docs/environment/timeouts.md new file mode 100644 index 000000000..3bba4032f --- /dev/null +++ b/docs/environment/timeouts.md @@ -0,0 +1,65 @@ +--- +title: Timeouts +current_menu: timeouts +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. + +Bref will throw an `LambdaTimeout` exception just before the Lambda actually times +out. This will allow your application to actually shutdown. + +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`. + +```php +if (isset($_SERVER['LAMBDA_TASK_ROOT'])) { + \Bref\Timeout\Timeout::enable(); +} +``` + +## Configuration + +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`. + +## 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: + +```php +generateResponse(); + } catch (LambdaTimeout $e) { + echo 'Oops, sorry. We spent too much time on this.'; + } catch (\Throwable $e) { + echo 'Some unexpected error happened.'; + } + } + + private function generateResponse() + { + $pi = // ... + echo 'Pi is '.$pi; + } +} + +return new Handler(); +``` From b89aa042ede0ec32789e16ad1eb8386f7166dc4c Mon Sep 17 00:00:00 2001 From: Nyholm Date: Fri, 26 Mar 2021 10:53:51 +0100 Subject: [PATCH 3/9] Adding a note about debugging --- docs/environment/timeouts.md | 9 +++++++++ 1 file changed, 9 insertions(+) diff --git a/docs/environment/timeouts.md b/docs/environment/timeouts.md index 3bba4032f..45dd99948 100644 --- a/docs/environment/timeouts.md +++ b/docs/environment/timeouts.md @@ -63,3 +63,12 @@ class Handler implements \Bref\Event\Handler 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. From 52f8d65f665f7f0be6ee5b0de13a70694466c1e4 Mon Sep 17 00:00:00 2001 From: Nyholm Date: Fri, 26 Mar 2021 10:57:54 +0100 Subject: [PATCH 4/9] Make Timeout::init() private --- src/Runtime/LambdaRuntime.php | 5 ----- src/Timeout/Timeout.php | 13 ++++--------- 2 files changed, 4 insertions(+), 14 deletions(-) diff --git a/src/Runtime/LambdaRuntime.php b/src/Runtime/LambdaRuntime.php index 43fe73030..bfd6c3d45 100755 --- a/src/Runtime/LambdaRuntime.php +++ b/src/Runtime/LambdaRuntime.php @@ -65,11 +65,6 @@ public function __construct(string $apiUrl, int $timeout = 0) $this->apiUrl = $apiUrl; $this->invoker = new Invoker; $this->timeout = $timeout; - - if ($timeout >= 0 && ! Timeout::init()) { - // If we fail to initialize - $this->timeout = -1; - } } public function __destruct() diff --git a/src/Timeout/Timeout.php b/src/Timeout/Timeout.php index f9c8fb64e..c903dac5f 100644 --- a/src/Timeout/Timeout.php +++ b/src/Timeout/Timeout.php @@ -45,20 +45,17 @@ public static function enable(): void } /** - * Setup custom handler for SIGTERM. One need to call Timeout::timoutAfter() - * to make an exception to be thrown. - * - * @return bool true if successful. + * Setup custom handler for SIGTERM. */ - public static function init(): bool + private static function init(): void { if (self::$initialized) { - return true; + return; } if (! function_exists('pcntl_async_signals')) { trigger_error('Could not enable timeout exceptions because pcntl extension is not enabled.'); - return false; + return; } pcntl_async_signals(true); @@ -67,8 +64,6 @@ public static function init(): bool }); self::$initialized = true; - - return true; } /** From 37a5759b6c0fab19f281629b7a4617777c903f55 Mon Sep 17 00:00:00 2001 From: Nyholm Date: Fri, 26 Mar 2021 11:47:16 +0100 Subject: [PATCH 5/9] Make this feature opt-in --- docs/environment/timeouts.md | 2 ++ src/Runtime/LambdaRuntime.php | 12 +++++++++++- tests/Runtime/LambdaRuntimeTest.php | 7 ++++++- 3 files changed, 19 insertions(+), 2 deletions(-) diff --git a/docs/environment/timeouts.md b/docs/environment/timeouts.md index 45dd99948..41f43ec6e 100644 --- a/docs/environment/timeouts.md +++ b/docs/environment/timeouts.md @@ -8,6 +8,8 @@ When a Lambda function times out, it is like the power to the computer is sudden 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. +> Note, this feature is experimental in Bref 1.3 and you need top opt-in by defining `BREF_TIMEOUT=0`. + Bref will throw an `LambdaTimeout` exception just before the Lambda actually times out. This will allow your application to actually shutdown. diff --git a/src/Runtime/LambdaRuntime.php b/src/Runtime/LambdaRuntime.php index bfd6c3d45..e20e19f6f 100755 --- a/src/Runtime/LambdaRuntime.php +++ b/src/Runtime/LambdaRuntime.php @@ -48,7 +48,17 @@ final class LambdaRuntime public static function fromEnvironmentVariable(?int $timeout = null): self { - return new self((string) getenv('AWS_LAMBDA_RUNTIME_API'), $timeout ?? (int) getenv('BREF_TIMEOUT')); + 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); } /** diff --git a/tests/Runtime/LambdaRuntimeTest.php b/tests/Runtime/LambdaRuntimeTest.php index df4faad3b..4dfa2cd2c 100644 --- a/tests/Runtime/LambdaRuntimeTest.php +++ b/tests/Runtime/LambdaRuntimeTest.php @@ -55,7 +55,12 @@ public function testFromEnvironmentVariable() putenv('AWS_LAMBDA_RUNTIME_API=foo'); putenv('BREF_TIMEOUT'); // unset - $this->assertEquals(0, $getTimeout(LambdaRuntime::fromEnvironmentVariable())); + + // In 1.3 this feature is opt-in only. + $this->assertEquals(-1, $getTimeout(LambdaRuntime::fromEnvironmentVariable())); + + // 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))); From a2e46ca0d743583bb16e933d75cbcedceaf9e652 Mon Sep 17 00:00:00 2001 From: Nyholm Date: Fri, 26 Mar 2021 12:35:04 +0100 Subject: [PATCH 6/9] Make sure the shutdown process has at least 1 second. --- src/Timeout/Timeout.php | 2 +- tests/Timeout/TimeoutTest.php | 4 ++-- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/src/Timeout/Timeout.php b/src/Timeout/Timeout.php index c903dac5f..c326dcd37 100644 --- a/src/Timeout/Timeout.php +++ b/src/Timeout/Timeout.php @@ -36,7 +36,7 @@ public static function enable(): void $deadlineMs = $context['deadlineMs']; $remainingTime = $deadlineMs - intval(microtime(true) * 1000); - self::timeoutAfter((int) floor($remainingTime / 1000)); + self::timeoutAfter(max(1, (int) floor($remainingTime / 1000) - 1)); return; } diff --git a/tests/Timeout/TimeoutTest.php b/tests/Timeout/TimeoutTest.php index c1138fb84..9f408257a 100644 --- a/tests/Timeout/TimeoutTest.php +++ b/tests/Timeout/TimeoutTest.php @@ -70,7 +70,7 @@ public function testEnableWithBrefTimeoutZeroAndContext() Timeout::enable(); $timeout = pcntl_alarm(0); - $this->assertEqualsWithDelta(30, $timeout, 1, 'BREF_TIMEOUT=0 should fallback to context'); + $this->assertEqualsWithDelta(29, $timeout, 1, 'BREF_TIMEOUT=0 should fallback to context'); } public function testEnableWithContext() @@ -79,7 +79,7 @@ public function testEnableWithContext() Timeout::enable(); $timeout = pcntl_alarm(0); - $this->assertEqualsWithDelta(30, $timeout, 1); + $this->assertEqualsWithDelta(29, $timeout, 1); } public function testTimeoutAfter() From 0b6d7b29b68c477955550beb05be6fd5bb90a9f5 Mon Sep 17 00:00:00 2001 From: Matthieu Napoli Date: Tue, 30 Mar 2021 11:43:05 +0200 Subject: [PATCH 7/9] Always base the timeout duration on the configured Lambda timeout (#3) * Always base the timeout duration on the configured Lambda timeout * Make sure that we can never enable the Bref timeout in the FPM bootstrap process * Remove unnecessary private method `timeoutAfter()` * Allow using falsy values for `BREF_FEATURE_TIMEOUT`, e.g. `0` or `''`, to allow disabling the feature * Cleanup global state * Improve tests following @Nyholm's feedback --- docs/environment/timeouts.md | 63 ++++++++++++----------------- runtime/layers/fpm/bootstrap | 12 +++++- src/Runtime/LambdaRuntime.php | 34 +++++----------- src/Timeout/Timeout.php | 63 ++++++++++++++--------------- tests/Runtime/LambdaRuntimeTest.php | 46 +++++++++++---------- tests/Server.php | 16 ++++++-- tests/Timeout/TimeoutTest.php | 60 +++++++-------------------- website/package-lock.json | 1 - 8 files changed, 125 insertions(+), 170 deletions(-) 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": { From 9356e4a4c913ac680c018a30598b13fb20831601 Mon Sep 17 00:00:00 2001 From: Nyholm Date: Tue, 30 Mar 2021 13:38:15 +0200 Subject: [PATCH 8/9] Do 2 alarms --- src/Timeout/Timeout.php | 30 +++++++++++++++++++++++++---- tests/Runtime/LambdaRuntimeTest.php | 2 ++ tests/Timeout/TimeoutTest.php | 11 ++++++----- 3 files changed, 34 insertions(+), 9 deletions(-) diff --git a/src/Timeout/Timeout.php b/src/Timeout/Timeout.php index 55091abde..e204e9177 100644 --- a/src/Timeout/Timeout.php +++ b/src/Timeout/Timeout.php @@ -11,6 +11,9 @@ final class Timeout /** @var bool */ private static $initialized = false; + /** @var string|null */ + private static $stackTrace = null; + /** * Automatically setup a timeout (based on the AWS Lambda timeout). * @@ -38,9 +41,9 @@ public static function enable(int $remainingTimeInMillis): void $remainingTimeInSeconds = (int) floor($remainingTimeInMillis / 1000); - // The script will timeout 1 second before the remaining time + // The script will timeout 2 seconds before the remaining time // to allow some time for Bref/our app to recover and cleanup - $margin = 1; + $margin = 2; $timeoutDelayInSeconds = max(1, $remainingTimeInSeconds - $margin); @@ -53,6 +56,8 @@ public static function enable(int $remainingTimeInMillis): void */ private static function init(): void { + Timeout::$stackTrace = null; + if (self::$initialized) { return; } @@ -66,14 +71,30 @@ private static function init(): void // 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'); + if (Timeout::$stackTrace !== null) { + // we already thrown an exception, do a harder exit. + error_log('Lambda timed out'); + error_log((new LambdaTimeout)->getTraceAsString()); + error_log('Original stack trace'); + error_log(Timeout::$stackTrace); + + exit(1); + } + + $exception = new LambdaTimeout('Maximum AWS Lambda execution time reached'); + Timeout::$stackTrace = $exception->getTraceAsString(); + + // Trigger another alarm after 1 second to do a hard exit. + pcntl_alarm(1); + + throw $exception; }); self::$initialized = true; } /** - * Reset timeout. + * Cancel all current timeouts. * * @internal */ @@ -81,6 +102,7 @@ public static function reset(): void { if (self::$initialized) { pcntl_alarm(0); + Timeout::$stackTrace = null; } } } diff --git a/tests/Runtime/LambdaRuntimeTest.php b/tests/Runtime/LambdaRuntimeTest.php index f6b6159ef..49cfc8360 100644 --- a/tests/Runtime/LambdaRuntimeTest.php +++ b/tests/Runtime/LambdaRuntimeTest.php @@ -16,6 +16,7 @@ use Bref\Runtime\LambdaRuntime; use Bref\Test\Server; use Bref\Timeout\LambdaTimeout; +use Bref\Timeout\Timeout; use GuzzleHttp\Psr7\Response; use PHPUnit\Framework\TestCase; use Psr\Http\Message\ResponseInterface; @@ -67,6 +68,7 @@ public function test Lambda timeouts can be anticipated() $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); + Timeout::reset(); $this->assertInvocationErrorResult(LambdaTimeout::class, 'Maximum AWS Lambda execution time reached'); $this->assertErrorInLogs(LambdaTimeout::class, 'Maximum AWS Lambda execution time reached'); diff --git a/tests/Timeout/TimeoutTest.php b/tests/Timeout/TimeoutTest.php index 7a000cc8d..4bc06085e 100644 --- a/tests/Timeout/TimeoutTest.php +++ b/tests/Timeout/TimeoutTest.php @@ -31,8 +31,8 @@ public function test enable() { Timeout::enable(3000); $timeout = pcntl_alarm(0); - // 2 seconds (1 second shorter than the 3s remaining time) - $this->assertSame(2, $timeout); + // 1 second (2 seconds shorter than the 3s remaining time) + $this->assertSame(1, $timeout); } public function test enable in FPM() @@ -41,7 +41,7 @@ public function test enable in FPM() Timeout::enableInFpm(); $timeout = pcntl_alarm(0); - $this->assertEqualsWithDelta(29, $timeout, 1); + $this->assertEqualsWithDelta(28, $timeout, 1); } public function test enable in FPM requires the context() @@ -53,13 +53,14 @@ public function test enable in FPM requires the context() public function test timeouts are interrupted in time() { $start = microtime(true); - Timeout::enable(2000); + Timeout::enable(3000); try { sleep(4); $this->fail('We expect a LambdaTimeout before we reach this line'); } catch (LambdaTimeout $e) { $time = 1000 * (microtime(true) - $start); - $this->assertEqualsWithDelta(1000, $time, 200, 'We must wait about 1 second'); + $this->assertEqualsWithDelta(2000, $time, 200, 'We must wait about 1 second'); + Timeout::reset(); } catch (\Throwable $e) { $this->fail('It must throw a LambdaTimeout.'); } From 2efd449e7c379ebe3a3ab7502b82e786cf75253b Mon Sep 17 00:00:00 2001 From: Nyholm Date: Tue, 30 Mar 2021 14:15:46 +0200 Subject: [PATCH 9/9] fixed tests --- src/Timeout/Timeout.php | 4 ++-- tests/Timeout/TimeoutTest.php | 2 +- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/src/Timeout/Timeout.php b/src/Timeout/Timeout.php index e204e9177..1facf95e7 100644 --- a/src/Timeout/Timeout.php +++ b/src/Timeout/Timeout.php @@ -56,7 +56,7 @@ public static function enable(int $remainingTimeInMillis): void */ private static function init(): void { - Timeout::$stackTrace = null; + self::$stackTrace = null; if (self::$initialized) { return; @@ -102,7 +102,7 @@ public static function reset(): void { if (self::$initialized) { pcntl_alarm(0); - Timeout::$stackTrace = null; + self::$stackTrace = null; } } } diff --git a/tests/Timeout/TimeoutTest.php b/tests/Timeout/TimeoutTest.php index 4bc06085e..ed44af498 100644 --- a/tests/Timeout/TimeoutTest.php +++ b/tests/Timeout/TimeoutTest.php @@ -59,7 +59,7 @@ public function test timeouts are interrupted in time() $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 1 second'); + $this->assertEqualsWithDelta(1000, $time, 200, 'We must wait about 1 second'); Timeout::reset(); } catch (\Throwable $e) { $this->fail('It must throw a LambdaTimeout.');