[Bref] Added support for handle timeouts

Author: Nyholm

src/bref/CHANGELOG.md

@@ -20,6 +20,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.
 
 ### Fixed
 

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.';
+        }
+    }
+}
+```

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;

src/bref/src/Timeout/LambdaTimeoutException.php

@@ -0,0 +1,14 @@
+<?php
+
+namespace Runtime\Bref\Timeout;
+
+/**
+ * The application took too long to produce a response. This exception is thrown
+ * to give the application a chance to flush logs and shut itself down before
+ * the power to AWS Lambda is disconnected.
+ *
+ * @author Tobias Nyholm <tobias.nyholm@gmail.com>
+ */
+class LambdaTimeoutException extends \RuntimeException
+{
+}

src/bref/src/Timeout/Timeout.php

@@ -0,0 +1,97 @@
+<?php
+
+namespace Runtime\Bref\Timeout;
+
+/**
+ * Helper class to trigger an exception just before the Lambda times out. This
+ * will give the application a chance to shut down.
+ *
+ * @author Tobias Nyholm <tobias.nyholm@gmail.com>
+ */
+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;
+        }
+    }
+}

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']);
     }
 

src/bref/tests/Timeout/TimeoutTest.php

@@ -0,0 +1,53 @@
+<?php
+
+namespace Runtime\Bref\Tests;
+
+use PHPUnit\Framework\TestCase;
+use Runtime\Bref\Timeout\LambdaTimeoutException;
+use Runtime\Bref\Timeout\Timeout;
+
+class TimeoutTest extends TestCase
+{
+    public static function setUpBeforeClass(): void
+    {
+        if (!function_exists('pcntl_async_signals')) {
+            self::markTestSkipped('PCNTL extension is not enabled.');
+        }
+    }
+
+    protected function setUp(): void
+    {
+        parent::setUp();
+        unset($_SERVER['LAMBDA_INVOCATION_CONTEXT']);
+    }
+
+    protected function tearDown(): void
+    {
+        Timeout::reset();
+        parent::tearDown();
+    }
+
+    public function testEnable()
+    {
+        Timeout::enable(3000);
+        $timeout = pcntl_alarm(0);
+        // 1 second (2 seconds shorter than the 3s remaining time)
+        $this->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.');
+        }
+    }
+}