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
brefphp · Mar 30, 2021 · 0b6d7b2 · 0b6d7b2
1 parent a2e46ca
commit 0b6d7b2
Show file tree

Hide file tree

Showing 8 changed files with 125 additions and 170 deletions.
diff --git 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
-<?php
+In `php-XX-fpm` layers, most frameworks will catch the `LambdaTimeout` exception automatically (like any other error).
 
-require dirname(__DIR__) . '/vendor/autoload.php';
+In `php-XX` layers, you can catch it in your handlers. For example:
 
+```php
 use Bref\Context\Context;
 use Bref\Timeout\LambdaTimeout;
 
@@ -48,29 +51,13 @@ class Handler implements \Bref\Event\Handler
     public function handle($event, Context $context)
     {
         try {
-            $this->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
@@ -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
@@ -43,38 +43,23 @@ 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');
         }
 
         $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
@@ -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,24 +63,19 @@ 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');
         });
 
         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
@@ -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
@@ -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;
     }