diff --git a/src/bref/CHANGELOG.md b/src/bref/CHANGELOG.md index e119405..f4e5360 100644 --- a/src/bref/CHANGELOG.md +++ b/src/bref/CHANGELOG.md @@ -14,6 +14,8 @@ you will get an exception. Run `composer require bref/bref` to solve the issue. - We do not use internal classes in Bref any more (https://github.com/php-runtime/runtime/pull/88) - Some handlers do not require the `bref/bref` package (https://github.com/php-runtime/runtime/pull/89) - We include a runtime specific Bref layer (https://github.com/php-runtime/bref-layer) +- Support for handle timeouts and lets your application shut down. This will shorten +the actual execution time with 2 seconds. ## 0.2.2 diff --git a/src/bref/README.md b/src/bref/README.md index e8a986d..8333cbb 100644 --- a/src/bref/README.md +++ b/src/bref/README.md @@ -14,6 +14,7 @@ We support all kinds of applications. See the following sections for details. 1. [Simplify serverless.yml](#simplify-serverlessyml) 1. [Typed handlers](#typed-handlers) 1. [Symfony Messenger integration](#symfony-messenger-integration) +1. [Handle timeouts](#handle-timeouts) If you are new to the Symfony Runtime component, read more in the [main readme](https://github.com/php-runtime/runtime). @@ -399,3 +400,43 @@ resources: QueueName: ${self:service}-workqueue VisibilityTimeout: 600 ``` + +## 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 shut down properly. +This leaves you without any logs and the problem could be hard to fix. + +To allow your application to shut down properly and write logs, we will throw an +exception just before the Lambda times out. + +Whenever a timeout happens, a full stack trace will be logged, including the line +that was executing. In most cases, it is an external call to a database, cache or +API that is stuck waiting. + +### Catching the exception + +You can catch the timeout exception to perform some cleanup, logs or even display +a proper error page. If you are using a framework, this is likely done for you. +Here is an example of a simple handler catching the timeout exception + +```php +use Bref\Context\Context; +use Bref\Event\Handler; +use Runtime\Bref\Timeout\LambdaTimeoutException; + +class MySlowHandler implements Handler +{ + public function handle($event, Context $context) + { + try { + // your code here + // ... + } catch (LambdaTimeoutException $e) { + return 'Oops, sorry. We spent too much time on this.'; + } catch (\Throwable $e) { + return 'Some other unexpected error happened.'; + } + } +} +``` diff --git a/src/bref/src/Lambda/LambdaClient.php b/src/bref/src/Lambda/LambdaClient.php index 1e851f9..c27a130 100755 --- a/src/bref/src/Lambda/LambdaClient.php +++ b/src/bref/src/Lambda/LambdaClient.php @@ -5,6 +5,7 @@ use Bref\Context\Context; use Bref\Event\Handler; use Exception; +use Runtime\Bref\Timeout\Timeout; /** * A port of LambdaRuntime from bref/bref package. That class is internal so @@ -100,6 +101,12 @@ public function processNextEvent(Handler $handler): bool [$event, $context] = $this->waitNextInvocation(); \assert($context instanceof Context); + $remainingTimeInMillis = $context->getRemainingTimeInMillis(); + if (0 < $remainingTimeInMillis) { + // Throw exception before Lambda pulls the plug. + Timeout::enable($remainingTimeInMillis); + } + $this->ping(); try { @@ -110,6 +117,8 @@ public function processNextEvent(Handler $handler): bool $this->signalFailure($context->getAwsRequestId(), $e); return false; + } finally { + Timeout::reset(); } return true; diff --git a/src/bref/src/Timeout/LambdaTimeoutException.php b/src/bref/src/Timeout/LambdaTimeoutException.php new file mode 100644 index 0000000..0e5c9bf --- /dev/null +++ b/src/bref/src/Timeout/LambdaTimeoutException.php @@ -0,0 +1,14 @@ + + */ +class LambdaTimeoutException extends \RuntimeException +{ +} diff --git a/src/bref/src/Timeout/Timeout.php b/src/bref/src/Timeout/Timeout.php new file mode 100644 index 0000000..000437f --- /dev/null +++ b/src/bref/src/Timeout/Timeout.php @@ -0,0 +1,97 @@ + + */ +final class Timeout +{ + /** @var bool */ + private static $initialized = false; + + /** @var string|null */ + private static $stackTrace = null; + + /** + * @internal + */ + public static function enable(int $remainingTimeInMillis): void + { + self::init(); + + if (!self::$initialized) { + return; + } + + $remainingTimeInSeconds = (int) floor($remainingTimeInMillis / 1000); + + // The script will timeout 2 seconds before the remaining time + // to allow some time for Bref/our app to recover and cleanup + $margin = 2; + + $timeoutDelayInSeconds = max(1, $remainingTimeInSeconds - $margin); + + // Trigger SIGALRM in X seconds + pcntl_alarm($timeoutDelayInSeconds); + } + + /** + * Setup custom handler for SIGALRM. + */ + private static function init(): void + { + self::$stackTrace = null; + + if (self::$initialized) { + return; + } + + if (!function_exists('pcntl_async_signals')) { + trigger_error('Could not enable timeout exceptions because pcntl extension is not enabled.'); + + return; + } + + 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 { + if (null !== Timeout::$stackTrace) { + // we have already thrown an exception, do a harder exit. + error_log('Lambda timed out'); + error_log((new LambdaTimeoutException())->getTraceAsString()); + error_log('Original stack trace'); + error_log(Timeout::$stackTrace); + + exit(1); + } + + $exception = new LambdaTimeoutException('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; + } + + /** + * Cancel all current timeouts. + * + * @internal + */ + public static function reset(): void + { + if (self::$initialized) { + pcntl_alarm(0); + self::$stackTrace = null; + } + } +} diff --git a/src/bref/tests/Lambda/LambdaClientTest.php b/src/bref/tests/Lambda/LambdaClientTest.php index 32211a3..7dc66d7 100644 --- a/src/bref/tests/Lambda/LambdaClientTest.php +++ b/src/bref/tests/Lambda/LambdaClientTest.php @@ -8,6 +8,8 @@ use GuzzleHttp\Server\Server; use PHPUnit\Framework\TestCase; use Runtime\Bref\Lambda\LambdaClient; +use Runtime\Bref\Timeout\LambdaTimeoutException; +use Runtime\Bref\Timeout\Timeout; /** * Tests the communication between `LambdaClient` and the Lambda Runtime HTTP API. @@ -189,9 +191,9 @@ public function handle($event, Context $context) // Check the lambda result contains the error message $error = json_decode((string) $eventFailureLog->getBody(), true); - $this->assertSame('Error while calling the Lambda runtime API: The requested URL returned error: 400 Bad Request', $error['errorMessage']); + $this->assertStringContainsString('Error while calling the Lambda runtime API: The requested URL returned error: 400', $error['errorMessage']); - $this->assertErrorInLogs('Exception', 'Error while calling the Lambda runtime API: The requested URL returned error: 400 Bad Request'); + $this->assertErrorInLogs('Exception', 'Error while calling the Lambda runtime API: The requested URL returned error: 400'); } public function test function results that cannot be encoded are reported as invocation errors() @@ -235,6 +237,28 @@ public function handle($event, Context $context) $this->assertInvocationResult(['foo' => 'bar']); } + public function testLambdaTimeoutsCanBeAnticipated() + { + $this->givenAnEvent([]); + + $start = microtime(true); + $this->lambda->processNextEvent(new class() implements Handler { + public function handle($event, Context $context) + { + // This 10s sleep should be interrupted + sleep(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); + Timeout::reset(); + + $this->assertInvocationErrorResult(LambdaTimeoutException::class, 'Maximum AWS Lambda execution time reached'); + $this->assertErrorInLogs(LambdaTimeoutException::class, 'Maximum AWS Lambda execution time reached'); + } + /** * @param mixed $event */ @@ -246,6 +270,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) ), @@ -312,7 +338,7 @@ private function assertErrorInLogs(string $errorClass, string $errorMessage): vo 'stack', ], array_keys($invocationResult)); $this->assertEquals($errorClass, $invocationResult['errorType']); - $this->assertEquals($errorMessage, $invocationResult['errorMessage']); + $this->assertStringContainsString($errorMessage, $invocationResult['errorMessage']); $this->assertIsArray($invocationResult['stack']); } diff --git a/src/bref/tests/Timeout/TimeoutTest.php b/src/bref/tests/Timeout/TimeoutTest.php new file mode 100644 index 0000000..0745c11 --- /dev/null +++ b/src/bref/tests/Timeout/TimeoutTest.php @@ -0,0 +1,53 @@ +assertSame(1, $timeout); + } + + public function testTimeoutsAreInterruptedInTime() + { + $start = microtime(true); + Timeout::enable(3000); + try { + sleep(4); + $this->fail('We expect a LambdaTimeout before we reach this line'); + } catch (LambdaTimeoutException $e) { + $time = 1000 * (microtime(true) - $start); + $this->assertEqualsWithDelta(1000, $time, 200, 'We must wait about 1 second'); + Timeout::reset(); + } catch (\Throwable $e) { + $this->fail('It must throw a LambdaTimeout.'); + } + } +}