Skip to content

Commit

Permalink
Merge pull request #590 from brefphp/exception-format
Browse files Browse the repository at this point in the history 
Cloudwatch logs formatted similar to native Runtime, v2
  • Loading branch information
@mnapoli
mnapoli authored Mar 14, 2020
2 parents 24294aa + a2b39a1 commit eec582c
Show file tree
Hide file tree
Showing 4 changed files with 164 additions and 72 deletions.
26 changes: 11 additions & 15 deletions src/Runtime/LambdaRuntime.php
View file
Original file line number Diff line number Diff line change
Expand Up @@ -78,7 +78,7 @@ private function closeReturnHandler(): void
/**
* Process the next event.
*
* @param Handler|callable $handler If it is a callable, it takes two parameters, an $event parameter (mixed) and a $context parameter (Context) and must return anything serializable to JSON.
* @param Handler|RequestHandlerInterface|callable $handler If it is a callable, it takes two parameters, an $event parameter (mixed) and a $context parameter (Context) and must return anything serializable to JSON.
*
* Example:
*
Expand Down Expand Up @@ -200,27 +200,23 @@ private function sendResponse(string $invocationId, $responseData): void
*/
private function signalFailure(string $invocationId, \Throwable $error): void
{
if ($error instanceof Exception) {
$errorMessage = 'Uncaught ' . get_class($error) . ': ' . $error->getMessage();
} else {
$errorMessage = $error->getMessage();
}
$stackTraceAsArray = explode(PHP_EOL, $error->getTraceAsString());

// Log the exception in CloudWatch
printf(
"Fatal error: %s in %s:%d\nStack trace:\n%s",
$errorMessage,
$error->getFile(),
$error->getLine(),
$error->getTraceAsString()
);
// We aim to use the same log format as what we can see when throwing an exception in the NodeJS runtime
// See https://github.com/brefphp/bref/pull/579
echo $invocationId . "\tInvoke Error\t" . json_encode([
'errorType' => get_class($error),
'errorMessage' => $error->getMessage(),
'stack' => $stackTraceAsArray,
]) . PHP_EOL;

// Send an "error" Lambda response
$url = "http://{$this->apiUrl}/2018-06-01/runtime/invocation/$invocationId/error";
$this->postJson($url, [
'errorMessage' => $error->getMessage(),
'errorType' => get_class($error),
'stackTrace' => explode(PHP_EOL, $error->getTraceAsString()),
'errorMessage' => $error->getMessage(),
'stackTrace' => $stackTraceAsArray,
]);
}

Expand Down
2 changes: 2 additions & 0 deletions tests/Handler/FpmHandlerTest.php
View file
Original file line number Diff line number Diff line change
Expand Up @@ -19,12 +19,14 @@ public function setUp(): void
{
parent::setUp();

ob_start();
$this->fakeContext = new Context('abc', time(), 'abc', 'abc');
}

public function tearDown()
{
$this->fpm->stop();
ob_end_clean();
}

public function test simple request()
Expand Down
96 changes: 75 additions & 21 deletions tests/Runtime/LambdaRuntimeTest.php
View file
Original file line number Diff line number Diff line change
Expand Up @@ -31,13 +31,15 @@ class LambdaRuntimeTest extends TestCase

protected function setUp()
{
ob_start();
Server::start();
$this->runtime = new LambdaRuntime('localhost:8126');
}

protected function tearDown()
{
Server::stop();
ob_end_clean();
}

public function test basic behavior()
Expand Down Expand Up @@ -65,6 +67,18 @@ public function test handler receives context()
]);
}

public function test exceptions in the handler result in an invocation error()
{
$this->givenAnEvent(['Hello' => 'world!']);

$this->runtime->processNextEvent(function () {
throw new \RuntimeException('This is an exception');
});

$this->assertInvocationErrorResult('RuntimeException', 'This is an exception');
$this->assertErrorInLogs('RuntimeException', 'This is an exception');
}

public function test an error is thrown if the runtime API returns a wrong response()
{
$this->expectExceptionMessage('Failed to fetch next Lambda invocation: The requested URL returned error: 404 Not Found');
Expand Down Expand Up @@ -141,9 +155,11 @@ public function test a wrong response from the runtime API turns the i
$this->assertSame('POST', $eventFailureLog->getMethod());
$this->assertSame('http://localhost:8126/2018-06-01/runtime/invocation/1/error', $eventFailureLog->getUri()->__toString());

$error = json_decode((string) $eventFailureLog->getBody());
$this->expectOutputRegex('/^Fatal error: Uncaught Exception: Error while calling the Lambda runtime API: The requested URL returned error: 400 Bad Request/');
$this->assertSame('Error while calling the Lambda runtime API: The requested URL returned error: 400 Bad Request', $error->errorMessage);
// 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->assertErrorInLogs('Exception', 'Error while calling the Lambda runtime API: The requested URL returned error: 400 Bad Request');
}

public function test function results that cannot be encoded are reported as invocation errors()
Expand All @@ -154,18 +170,13 @@ public function test function results that cannot be encoded are reporte
return "\xB1\x31";
});

$requests = Server::received();
$this->assertCount(2, $requests);

[$eventRequest, $eventFailureLog] = $requests;
$this->assertSame('GET', $eventRequest->getMethod());
$this->assertSame('http://localhost:8126/2018-06-01/runtime/invocation/next', $eventRequest->getUri()->__toString());
$this->assertSame('POST', $eventFailureLog->getMethod());
$this->assertSame('http://localhost:8126/2018-06-01/runtime/invocation/1/error', $eventFailureLog->getUri()->__toString());

$error = json_decode((string) $eventFailureLog->getBody());
$this->expectOutputRegex('/^Fatal error: Uncaught Exception: The Lambda response cannot be encoded to JSON/');
$this->assertSame("The Lambda response cannot be encoded to JSON.\nThis error usually happens when you try to return binary content. If you are writing a HTTP application and you want to return a binary HTTP response (like an image, a PDF, etc.), please read this guide: https://bref.sh/docs/runtimes/http.html#binary-responses\nHere is the original JSON error: 'Malformed UTF-8 characters, possibly incorrectly encoded'", $error->errorMessage);
$message = <<<ERROR
The Lambda response cannot be encoded to JSON.
This error usually happens when you try to return binary content. If you are writing a HTTP application and you want to return a binary HTTP response (like an image, a PDF, etc.), please read this guide: https://bref.sh/docs/runtimes/http.html#binary-responses
Here is the original JSON error: 'Malformed UTF-8 characters, possibly incorrectly encoded'
ERROR;
$this->assertInvocationErrorResult('Exception', $message);
$this->assertErrorInLogs('Exception', $message);
}

public function test generic event handler()
Expand Down Expand Up @@ -282,11 +293,8 @@ public function test invalid handlers are rejected properly()

$this->runtime->processNextEvent(null);

$requests = Server::received();
$this->assertCount(2, $requests);
$error = json_decode((string) $requests[1]->getBody(), true);
$this->expectOutputRegex('/^Fatal error: Uncaught Exception: The lambda handler must be a callable or implement handler interfaces/');
$this->assertSame('The lambda handler must be a callable or implement handler interfaces', $error['errorMessage']);
$this->assertInvocationErrorResult('Exception', 'The lambda handler must be a callable or implement handler interfaces');
$this->assertErrorInLogs('Exception', 'The lambda handler must be a callable or implement handler interfaces');
}

/**
Expand All @@ -298,7 +306,7 @@ private function givenAnEvent($event): void
new Response( // lambda event
200,
[
'lambda-runtime-aws-request-id' => 1,
'lambda-runtime-aws-request-id' => '1',
'lambda-runtime-invoked-function-arn' => 'test-function-name',
],
json_encode($event)
Expand All @@ -322,4 +330,50 @@ private function assertInvocationResult($result)
$this->assertSame('http://localhost:8126/2018-06-01/runtime/invocation/1/response', $eventResponse->getUri()->__toString());
$this->assertEquals($result, json_decode($eventResponse->getBody()->__toString(), true));
}

private function assertInvocationErrorResult(string $errorClass, string $errorMessage)
{
$requests = Server::received();
$this->assertCount(2, $requests);

[$eventRequest, $eventResponse] = $requests;
$this->assertSame('GET', $eventRequest->getMethod());
$this->assertSame('http://localhost:8126/2018-06-01/runtime/invocation/next', $eventRequest->getUri()->__toString());
$this->assertSame('POST', $eventResponse->getMethod());
$this->assertSame('http://localhost:8126/2018-06-01/runtime/invocation/1/error', $eventResponse->getUri()->__toString());

// Check the content of the result of the lambda
$invocationResult = json_decode($eventResponse->getBody()->__toString(), true);
$this->assertSame([
'errorType',
'errorMessage',
'stackTrace',
], array_keys($invocationResult));
$this->assertEquals($errorClass, $invocationResult['errorType']);
$this->assertEquals($errorMessage, $invocationResult['errorMessage']);
$this->assertInternalType('array', $invocationResult['stackTrace']);
}

private function assertErrorInLogs(string $errorClass, string $errorMessage): void
{
// Decode the logs from stdout
$stdout = $this->getActualOutput();

[$requestId, $message, $json] = explode("\t", $stdout);

$this->assertSame('Invoke Error', $message);

// Check the request ID matches a UUID
$this->assertNotEmpty($requestId);

$invocationResult = json_decode($json, true);
$this->assertSame([
'errorType',
'errorMessage',
'stack',
], array_keys($invocationResult));
$this->assertEquals($errorClass, $invocationResult['errorType']);
$this->assertEquals($errorMessage, $invocationResult['errorMessage']);
$this->assertInternalType('array', $invocationResult['stack']);
}
}
112 changes: 76 additions & 36 deletions tests/Sam/PhpRuntimeTest.php
View file
Original file line number Diff line number Diff line change
Expand Up @@ -59,23 +59,13 @@ public function test uncaught exception appears in logs and is reported
'exception' => true,
]);

// We don't assert on complete exception traces because they will change over time
$expectedLogs = <<<LOGS
Fatal error: Uncaught Exception: This is an uncaught exception in /var/task/tests/Sam/Php/function.php:35
Stack trace:
#0 /var/task/
LOGS;
self::assertContains($expectedLogs, $logs);

// Check the exception is returned as the lambda result
self::assertSame([
'errorType',
'errorMessage',
'stackTrace',
], array_keys($result));
self::assertSame('Exception', $result['errorType']);
self::assertSame('This is an uncaught exception', $result['errorMessage']);
self::assertStringStartsWith('#0 /var/task/', $result['stackTrace'][0]);
$this->assertInvocationError(
$result,
$logs,
'Exception',
'This is an uncaught exception',
'#0 /var/task/src/Runtime/LambdaRuntime.php('
);
}

public function test error appears in logs and is reported as an invocation error()
Expand All @@ -84,23 +74,13 @@ public function test error appears in logs and is reported as an invoc
'error' => true,
]);

// We don't assert on complete exception traces because they will change over time
$expectedLogs = <<<LOGS
Fatal error: strlen() expects exactly 1 parameter, 0 given in /var/task/tests/Sam/Php/function.php:39
Stack trace:
#0 /var/task/
LOGS;
self::assertContains($expectedLogs, $logs);

// Check the exception is returned as the lambda result
self::assertSame([
'errorType',
'errorMessage',
'stackTrace',
], array_keys($result));
self::assertSame('ArgumentCountError', $result['errorType']);
self::assertSame('strlen() expects exactly 1 parameter, 0 given', $result['errorMessage']);
self::assertStringStartsWith('#0 /var/task/', $result['stackTrace'][0]);
$this->assertInvocationError(
$result,
$logs,
'ArgumentCountError',
'strlen() expects exactly 1 parameter, 0 given',
'#0 /var/task/tests/Sam/Php/function.php(39)'
);
}

public function test fatal error appears in logs and is reported as an invocation error()
Expand Down Expand Up @@ -131,8 +111,10 @@ public function test warnings are logged()
'warning' => true,
]);

self::assertNotContains('Warning: This is a test warning', $result);
self::assertContains('Warning: This is a test warning in /var/task/tests/Sam/Php/function.php', $logs);
// The warning does not turn the execution into an error
$this->assertEquals('Hello world', $result);
// But it appears in the logs
$this->assertContains('Warning: This is a test warning in /var/task/tests/Sam/Php/function.php', $logs);
}

public function test php extensions()
Expand Down Expand Up @@ -292,4 +274,62 @@ private function invokeLambda($event = null): array

return [$result, $logs];
}

private function assertInvocationError(
array $invocationResult,
string $logs,
string $errorClass,
string $errorMessage,
string $stackTraceStartsWith = '#0 /var/task/'
): void {
$this->assertSame([
'errorType',
'errorMessage',
'stackTrace',
], array_keys($invocationResult));
$this->assertEquals($errorClass, $invocationResult['errorType']);
$this->assertEquals($errorMessage, $invocationResult['errorMessage']);
$this->assertInternalType('array', $invocationResult['stackTrace']);
$this->assertStringStartsWith($stackTraceStartsWith, $invocationResult['stackTrace'][0]);

$this->assertErrorInLogs($logs, $errorClass, $errorMessage, $stackTraceStartsWith);
}

private function assertErrorInLogs(
string $logs,
string $errorClass,
string $errorMessage,
string $stackTraceStartsWith = '#0 /var/task/'
): void {
// Extract the only interesting log line
$logLines = explode("\n", $logs);
$logLines = array_filter($logLines, function (string $line): bool {
$line = trim($line);
return $line !== ''
&& (strpos($line, 'START') !== 0)
&& (strpos($line, 'END') !== 0)
&& (strpos($line, 'REPORT') !== 0);
});
$this->assertCount(1, $logLines);
$logLine = reset($logLines);

// Decode the logs from stdout
[$requestId, $message, $json] = explode("\t", $logLine);

// Check the request ID matches a UUID
$this->assertRegExp('/[0-9a-fA-F]{8}\-[0-9a-fA-F]{4}\-[0-9a-fA-F]{4}\-[0-9a-fA-F]{4}\-[0-9a-fA-F]{12}/', $requestId);

$this->assertSame('Invoke Error', $message);

$invocationResult = json_decode($json, true);
$this->assertSame([
'errorType',
'errorMessage',
'stack',
], array_keys($invocationResult));
$this->assertEquals($errorClass, $invocationResult['errorType']);
$this->assertEquals($errorMessage, $invocationResult['errorMessage']);
$this->assertInternalType('array', $invocationResult['stack']);
$this->assertStringStartsWith($stackTraceStartsWith, $invocationResult['stack'][0]);
}
}

0 comments on commit eec582c

Please sign in to comment.