From 6797aa5f6a0835413c04528fed441d70f79aaaf9 Mon Sep 17 00:00:00 2001 From: Aran Reeks Date: Sun, 14 Feb 2021 00:32:42 +0000 Subject: [PATCH 1/5] Added Lambda and API Gateway request IDs to Cloudwatch logs when there's a PHP-FPM issue --- src/Event/Http/FpmHandler.php | 51 ++++++++++++++++++++++++++++++----- 1 file changed, 44 insertions(+), 7 deletions(-) diff --git a/src/Event/Http/FpmHandler.php b/src/Event/Http/FpmHandler.php index d31783bbd..f2ea19b88 100644 --- a/src/Event/Http/FpmHandler.php +++ b/src/Event/Http/FpmHandler.php @@ -49,6 +49,9 @@ final class FpmHandler extends HttpHandler /** @var Process|null */ private $fpm; + private $lambdaRequestId; + private $apiGatewayRequestId; + public function __construct(string $handler, string $configFile = self::CONFIG) { $this->handler = $handler; @@ -79,7 +82,7 @@ public function start(): void $this->fpm->setTimeout(null); $this->fpm->start(function ($type, $output): void { // Send any PHP-FPM log to CloudWatch - echo $output; + $this->logToCloudwatch($output); }); $this->client = new Client; @@ -108,16 +111,19 @@ public function __destruct() */ public function handleRequest(HttpRequestEvent $event, Context $context): HttpResponse { + $this->lambdaRequestId = $context->getAwsRequestId(); + $this->apiGatewayRequestId = $event->getRequestContext()['requestId']; + $request = $this->eventToFastCgiRequest($event, $context); try { $response = $this->client->sendRequest($this->connection, $request); } catch (Throwable $e) { - printf( - "Error communicating with PHP-FPM to read the HTTP response. A root cause of this can be that the Lambda (or PHP) timed out, for example when trying to connect to a remote API or database, if this happens continuously check for those! Bref will restart PHP-FPM now. Original exception message: %s %s\n", + $this->logToCloudwatch(sprintf( + "Error communicating with PHP-FPM to read the HTTP response. A root cause of this can be that the Lambda (or PHP) timed out, for example when trying to connect to a remote API or database, if this happens continuously check for those! Bref will restart PHP-FPM now. Original exception message: %s %s", get_class($e), $e->getMessage() - ); + )); // Restart PHP-FPM: in some cases PHP-FPM is borked, that's the only way we can recover $this->stop(); @@ -221,7 +227,7 @@ private function killExistingFpm(): void // Never seen this happen but just in case if ($pid <= 0) { - echo "PHP-FPM's PID file contained an invalid PID, assuming PHP-FPM isn't running.\n"; + $this->logToCloudwatch("PHP-FPM's PID file contained an invalid PID, assuming PHP-FPM isn't running."); unlink(self::SOCKET); unlink(self::PID_FILE); return; @@ -243,12 +249,12 @@ private function killExistingFpm(): void return; } - echo "PHP-FPM seems to be running already. This might be because Lambda stopped the bootstrap process but didn't leave us an opportunity to stop PHP-FPM (did Lambda timeout?). Stopping PHP-FPM now to restart from a blank slate.\n"; + $this->logToCloudwatch("PHP-FPM seems to be running already. This might be because Lambda stopped the bootstrap process but didn't leave us an opportunity to stop PHP-FPM (did Lambda timeout?). Stopping PHP-FPM now to restart from a blank slate."); // The previous PHP-FPM process is running, let's try to kill it properly $result = posix_kill($pid, self::SIGTERM); if ($result === false) { - echo "PHP-FPM's PID file contained a PID that doesn't exist, assuming PHP-FPM isn't running.\n"; + $this->logToCloudwatch("PHP-FPM's PID file contained a PID that doesn't exist, assuming PHP-FPM isn't running."); unlink(self::SOCKET); unlink(self::PID_FILE); return; @@ -282,4 +288,35 @@ private function getResponseHeaders(ProvidesResponseData $response): array { return array_change_key_case($response->getHeaders(), CASE_LOWER); } + + /** + * Log a message to Cloudwatch, this is specific for FPM related errors and will include AWS Request IDs for the + * current Lambda invocation and API Gateway (where applicable) to aid debugging any FPM-related issues. + * + * @param string $message + */ + private function logToCloudwatch(string $message): void + { + echo trim($message) . ' ' . json_encode($this->getLogContext()) . PHP_EOL; + } + + /** + * Returns an array with AWS Request IDs for the current Lambda invocation and API Gateway (where applicable) + * + * @return string[]|array + */ + private function getLogContext(): array + { + $logContext = []; + + if ($this->lambdaRequestId) { + $logContext['lambdaRequestId'] = $this->lambdaRequestId; + } + + if ($this->apiGatewayRequestId) { + $logContext['apiGatewayRequestId'] = $this->apiGatewayRequestId; + } + + return $logContext; + } } From ba5db5934b8dbb1e9e0a465a5e3e8c3ae48f5077 Mon Sep 17 00:00:00 2001 From: Aran Reeks Date: Sun, 14 Feb 2021 00:36:17 +0000 Subject: [PATCH 2/5] PHP CodeSniffer amends --- src/Event/Http/FpmHandler.php | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/src/Event/Http/FpmHandler.php b/src/Event/Http/FpmHandler.php index f2ea19b88..2e392a4d1 100644 --- a/src/Event/Http/FpmHandler.php +++ b/src/Event/Http/FpmHandler.php @@ -49,7 +49,9 @@ final class FpmHandler extends HttpHandler /** @var Process|null */ private $fpm; + /** @var string */ private $lambdaRequestId; + /** @var string */ private $apiGatewayRequestId; public function __construct(string $handler, string $configFile = self::CONFIG) @@ -120,7 +122,7 @@ public function handleRequest(HttpRequestEvent $event, Context $context): HttpRe $response = $this->client->sendRequest($this->connection, $request); } catch (Throwable $e) { $this->logToCloudwatch(sprintf( - "Error communicating with PHP-FPM to read the HTTP response. A root cause of this can be that the Lambda (or PHP) timed out, for example when trying to connect to a remote API or database, if this happens continuously check for those! Bref will restart PHP-FPM now. Original exception message: %s %s", + 'Error communicating with PHP-FPM to read the HTTP response. A root cause of this can be that the Lambda (or PHP) timed out, for example when trying to connect to a remote API or database, if this happens continuously check for those! Bref will restart PHP-FPM now. Original exception message: %s %s', get_class($e), $e->getMessage() )); @@ -292,8 +294,6 @@ private function getResponseHeaders(ProvidesResponseData $response): array /** * Log a message to Cloudwatch, this is specific for FPM related errors and will include AWS Request IDs for the * current Lambda invocation and API Gateway (where applicable) to aid debugging any FPM-related issues. - * - * @param string $message */ private function logToCloudwatch(string $message): void { From 8890e1d1b25ae6cf7f93eef00b83f845b315687c Mon Sep 17 00:00:00 2001 From: Aran Reeks Date: Sun, 14 Feb 2021 00:37:33 +0000 Subject: [PATCH 3/5] Fix for Undefined array key "requestId" in unit tests --- src/Event/Http/FpmHandler.php | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/Event/Http/FpmHandler.php b/src/Event/Http/FpmHandler.php index 2e392a4d1..88ff8b250 100644 --- a/src/Event/Http/FpmHandler.php +++ b/src/Event/Http/FpmHandler.php @@ -114,7 +114,7 @@ public function __destruct() public function handleRequest(HttpRequestEvent $event, Context $context): HttpResponse { $this->lambdaRequestId = $context->getAwsRequestId(); - $this->apiGatewayRequestId = $event->getRequestContext()['requestId']; + $this->apiGatewayRequestId = $event->getRequestContext()['requestId'] ?? null; $request = $this->eventToFastCgiRequest($event, $context); From ccc3e376845d0108f1f419eaaab2bef262be6be4 Mon Sep 17 00:00:00 2001 From: Aran Reeks Date: Sat, 27 Feb 2021 00:20:47 +0000 Subject: [PATCH 4/5] Normalise naming conventions Co-authored-by: Matthieu Napoli --- src/Event/Http/FpmHandler.php | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/Event/Http/FpmHandler.php b/src/Event/Http/FpmHandler.php index 88ff8b250..249b827c7 100644 --- a/src/Event/Http/FpmHandler.php +++ b/src/Event/Http/FpmHandler.php @@ -310,7 +310,7 @@ private function getLogContext(): array $logContext = []; if ($this->lambdaRequestId) { - $logContext['lambdaRequestId'] = $this->lambdaRequestId; + $logContext['requestId'] = $this->lambdaRequestId; } if ($this->apiGatewayRequestId) { From 318781d32da613a4a8ada7922dfe4a02bc35a255 Mon Sep 17 00:00:00 2001 From: Aran Reeks Date: Sat, 27 Feb 2021 00:25:08 +0000 Subject: [PATCH 5/5] Reverted FPM logging --- src/Event/Http/FpmHandler.php | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/Event/Http/FpmHandler.php b/src/Event/Http/FpmHandler.php index 249b827c7..009c029cb 100644 --- a/src/Event/Http/FpmHandler.php +++ b/src/Event/Http/FpmHandler.php @@ -84,7 +84,7 @@ public function start(): void $this->fpm->setTimeout(null); $this->fpm->start(function ($type, $output): void { // Send any PHP-FPM log to CloudWatch - $this->logToCloudwatch($output); + echo $output; }); $this->client = new Client;