From 95b0ddc2caff53545f0dd1bcebacc55054057313 Mon Sep 17 00:00:00 2001 From: Edie Lemoine Date: Thu, 24 Oct 2024 13:53:06 +0200 Subject: [PATCH] feat: improve logging (#310) --- src/Api/Exception/ApiException.php | 2 +- src/Api/Service/AbstractApiService.php | 38 +++-- src/App/Api/PdkEndpoint.php | 92 +++++++---- tests/Bootstrap/MockApiExceptionAction.php | 42 +++++ tests/Bootstrap/MockExceptionAction.php | 25 +++ tests/Unit/Base/PdkEndpointTest.php | 169 +++++++++++++++++---- 6 files changed, 293 insertions(+), 75 deletions(-) create mode 100644 tests/Bootstrap/MockApiExceptionAction.php create mode 100644 tests/Bootstrap/MockExceptionAction.php diff --git a/src/Api/Exception/ApiException.php b/src/Api/Exception/ApiException.php index c38daeb95..b69590749 100644 --- a/src/Api/Exception/ApiException.php +++ b/src/Api/Exception/ApiException.php @@ -40,7 +40,7 @@ public function __construct(ClientResponseInterface $response, int $code = 0, Th parent::__construct( sprintf( - 'Request failed. Status code: %s. Errors: %s', + 'Request failed. Status code: %s. Message: %s', $response->getStatusCode(), $body['message'] ), diff --git a/src/Api/Service/AbstractApiService.php b/src/Api/Service/AbstractApiService.php index 9f79a1d3e..bd064899c 100644 --- a/src/Api/Service/AbstractApiService.php +++ b/src/Api/Service/AbstractApiService.php @@ -55,43 +55,41 @@ public function doRequest( ]; $logContext = [ - 'uri' => $uri, - 'method' => $method, - 'headers' => $options['headers'], - 'body' => $options['body'] ? json_decode($options['body'], true) : null, + 'request' => [ + 'uri' => $uri, + 'method' => $method, + 'headers' => $options['headers'], + 'body' => $options['body'] ? json_decode($options['body'], true) : null, + ], ]; - Logger::debug('Sending request to MyParcel', $logContext); - try { $response = $this->clientAdapter->doRequest($method, $uri, $options); } catch (Throwable $e) { Logger::error( - 'Error sending request to MyParcel', - ['error' => $e->getMessage()] + $logContext + 'An exception was thrown while sending request', + array_replace($logContext, ['error' => $e->getMessage()]) ); + throw new RuntimeException($e->getMessage(), $e->getCode(), $e); } /** @var \MyParcelNL\Pdk\Api\Contract\ApiResponseInterface $responseObject */ $responseObject = new $responseClass($response); + $body = $responseObject->getBody(); + + $logContext['response'] = [ + 'code' => $responseObject->getStatusCode(), + 'body' => $body ? json_decode($body, true) : null, + ]; if ($responseObject->isErrorResponse()) { - Logger::error( - 'Received an error response from MyParcel', - [ - 'code' => $response->getStatusCode(), - 'errors' => $responseObject->getErrors(), - ] + $logContext - ); + Logger::error('Received an error response', $logContext); + throw new ApiException($response); } - $body = $responseObject->getBody(); - - Logger::debug('Received response from MyParcel', [ - 'response' => $body ? json_decode($body, true) : null, - ]); + Logger::debug('Successfully sent request', $logContext); return $responseObject; } diff --git a/src/App/Api/PdkEndpoint.php b/src/App/Api/PdkEndpoint.php index 01d8bd9b6..bd0fa0768 100644 --- a/src/App/Api/PdkEndpoint.php +++ b/src/App/Api/PdkEndpoint.php @@ -7,6 +7,7 @@ use MyParcelNL\Pdk\Api\Exception\ApiException; use MyParcelNL\Pdk\Api\Exception\PdkEndpointException; use MyParcelNL\Pdk\App\Api\Contract\PdkApiInterface; +use MyParcelNL\Pdk\Facade\Logger; use MyParcelNL\Pdk\Facade\Pdk; use Symfony\Component\HttpFoundation\JsonResponse; use Symfony\Component\HttpFoundation\Response; @@ -49,11 +50,23 @@ public function call($input, string $context): Response ->setContext($context) ->execute($input); } catch (ApiException $e) { + // In case of an ApiException, AbstractApiService has already logged the error. return $this->createApiErrorResponse($e); - } catch (PdkEndpointException $e) { - return $this->createErrorResponse($e, $e->getStatusCode()); } catch (Throwable $e) { - return $this->createErrorResponse($e); + if ($e instanceof PdkEndpointException) { + $response = $this->createErrorResponse($context, $e, $e->getStatusCode()); + } else { + $response = $this->createErrorResponse($context, $e); + } + + Logger::error('An exception was thrown while executing an action', [ + 'action' => is_string($input) ? $input : $input->get('action') ?? 'unknown', + 'context' => $context, + // Pass backend context to log stack traces. + 'response' => $this->createErrorContext(self::CONTEXT_BACKEND, $e), + ]); + + return $response; } } @@ -64,41 +77,66 @@ public function call($input, string $context): Response */ public function createApiErrorResponse(ApiException $exception): JsonResponse { - return new JsonResponse( - [ - 'message' => $exception->getMessage(), - 'request_id' => $exception->getRequestId(), - 'errors' => $exception->getErrors(), - ], - Response::HTTP_BAD_REQUEST - ); + return new JsonResponse([ + 'message' => $exception->getMessage(), + 'request_id' => $exception->getRequestId(), + 'errors' => $exception->getErrors(), + ], Response::HTTP_BAD_REQUEST); } /** + * @param string $context * @param \Throwable $throwable * @param int $statusCode * * @return \Symfony\Component\HttpFoundation\JsonResponse */ protected function createErrorResponse( + string $context, Throwable $throwable, int $statusCode = Response::HTTP_BAD_REQUEST ): JsonResponse { - return new JsonResponse( - [ - 'message' => $throwable->getMessage(), - 'errors' => [ - [ - 'status' => $statusCode, - 'code' => $throwable->getCode(), - 'message' => $throwable->getMessage(), - 'trace' => Pdk::isDevelopment() - ? $throwable->getTrace() - : 'Enable development mode to see stack trace.', - ], - ], - ], - $statusCode - ); + return new JsonResponse($this->createErrorContext($context, $throwable), $statusCode); + } + + /** + * @param string $context + * @param \Throwable $throwable + * + * @return array + */ + private function createErrorContext(string $context, Throwable $throwable): array + { + $firstThrowable = $throwable; + $errors = [$this->formatThrowable($firstThrowable, $context)]; + + while ($throwable = $throwable->getPrevious()) { + $errors[] = $this->formatThrowable($throwable, $context); + } + + return [ + 'message' => $firstThrowable->getMessage(), + 'errors' => $errors, + ]; + } + + /** + * @param \Throwable $throwable + * @param string $context + * + * @return array + */ + private function formatThrowable(Throwable $throwable, string $context): array + { + return [ + 'code' => $throwable->getCode(), + 'message' => $throwable->getMessage(), + 'file' => $throwable->getFile(), + 'line' => $throwable->getLine(), + // Hide stack trace in frontend contexts unless in development mode + 'trace' => $context === self::CONTEXT_BACKEND || Pdk::isDevelopment() + ? $throwable->getTrace() + : 'Enable development mode to see stack trace.', + ]; } } diff --git a/tests/Bootstrap/MockApiExceptionAction.php b/tests/Bootstrap/MockApiExceptionAction.php new file mode 100644 index 000000000..3c8a233e4 --- /dev/null +++ b/tests/Bootstrap/MockApiExceptionAction.php @@ -0,0 +1,42 @@ + 'boom', + 'errors' => [ + [ + 'code' => 24920, + 'message' => 'Something went wrong', + ], + [ + 'code' => 74892, + 'message' => 'Something else also went wrong', + ], + ], + 'request_id' => '12345', + ]; + + $response = new ClientResponse(json_encode($body), Response::HTTP_BAD_REQUEST); + + throw new ApiException($response); + } +} diff --git a/tests/Bootstrap/MockExceptionAction.php b/tests/Bootstrap/MockExceptionAction.php new file mode 100644 index 000000000..1c26bcd6a --- /dev/null +++ b/tests/Bootstrap/MockExceptionAction.php @@ -0,0 +1,25 @@ +group('endpoints'); @@ -62,7 +67,7 @@ ]) ); -dataset('backendActions', function () { +dataset('backend actions', function () { return [ PdkBackendActions::CREATE_WEBHOOKS, PdkBackendActions::DELETE_ACCOUNT, @@ -85,7 +90,7 @@ ]; }); -dataset('frontendActions', function () { +dataset('frontend actions', function () { return [ PdkFrontendActions::FETCH_CHECKOUT_CONTEXT, PdkSharedActions::FETCH_CONTEXT, @@ -106,49 +111,95 @@ function testEndpoint(string $action, string $context): void it('calls pdk backend endpoints', function (string $action) { testEndpoint($action, PdkEndpoint::CONTEXT_BACKEND); -}) - ->with('backendActions'); +})->with('backend actions'); it('calls pdk frontend endpoints', function (string $action) { testEndpoint($action, PdkEndpoint::CONTEXT_FRONTEND); -}) - ->with('frontendActions'); +})->with('frontend actions'); -it('returns error response on nonexistent action', function () { +it('returns and logs error response when error is thrown', function () { /** @var PdkEndpoint $endpoint */ $endpoint = Pdk::get(PdkEndpoint::class); + /** @var \MyParcelNL\Pdk\Tests\Bootstrap\MockLogger $logger */ + $logger = Pdk::get(LoggerInterface::class); + $response = $endpoint->call('nonexistent', PdkEndpoint::CONTEXT_BACKEND); + $responseContent = json_decode($response->getContent(), true); + $logs = $logger->getLogs(); + + // Check if the file and line are set. + expect(Arr::get($responseContent, 'errors.0.file')) + ->toMatch('/\.php$/') + ->and(Arr::get($responseContent, 'errors.0.line')) + ->toBeInt(); + + // Remove trace properties before comparing as they are not static. + Arr::forget($responseContent, 'errors.0.trace'); + Arr::forget($logs, '0.context.response.errors.0.trace'); + + $responseContext = [ + 'message' => 'Action "nonexistent" does not exist.', + 'errors' => [ + // Add the expected error response to the response context so that we don't have to manually compare the + // file and line as they can change. + array_replace(Arr::get($responseContent, 'errors.0'), [ + 'message' => 'Action "nonexistent" does not exist.', + 'code' => 0, + ]), + ], + ]; + expect($response->getStatusCode()) ->toBe(Response::HTTP_UNPROCESSABLE_ENTITY) - ->and(json_decode($response->getContent(), true)) + ->and($responseContent) + ->toBe($responseContext) + ->and($logs) ->toBe([ - 'message' => 'Action "nonexistent" does not exist.', - 'errors' => [ - [ - 'status' => 422, - 'code' => 0, - 'message' => 'Action "nonexistent" does not exist.', - 'trace' => 'Enable development mode to see stack trace.', + [ + 'level' => 'error', + 'message' => '[PDK]: An exception was thrown while executing an action', + 'context' => [ + 'action' => 'nonexistent', + 'context' => PdkEndpoint::CONTEXT_BACKEND, + 'response' => $responseContext, ], ], ]); }); -it('shows stack trace in development mode', function () { +it('hides stack trace in frontend context', function () { + /** @var PdkEndpoint $endpoint */ + $endpoint = Pdk::get(PdkEndpoint::class); + $response = $endpoint->call('nonexistent', PdkEndpoint::CONTEXT_FRONTEND); + + expect($response->getStatusCode()) + ->toBe(Response::HTTP_UNPROCESSABLE_ENTITY) + ->and(json_decode($response->getContent(), true)['errors'][0]['trace']) + ->toBe('Enable development mode to see stack trace.'); +}); + +it('shows stack trace in frontend context in development mode', function () { PdkFactory::create(MockPdkConfig::create(['mode' => value(\MyParcelNL\Pdk\Base\Pdk::MODE_DEVELOPMENT)])); /** @var PdkEndpoint $endpoint */ $endpoint = Pdk::get(PdkEndpoint::class); - $response = $endpoint->call('nonexistent', PdkEndpoint::CONTEXT_BACKEND); + + $response = $endpoint->call('nonexistent', PdkEndpoint::CONTEXT_FRONTEND); + + $trace = Arr::get(json_decode($response->getContent(), true), 'errors.0.trace'); expect($response->getStatusCode()) ->toBe(Response::HTTP_UNPROCESSABLE_ENTITY) - ->and(json_decode($response->getContent(), true)['errors'][0]['trace']) - ->toBeArray(); + ->and($trace) + ->toBeArray() + ->and($trace) + ->not->toBeEmpty() + ->and($trace[0]) + ->toHaveKeys(['file', 'line', 'function', 'class']); }); -it('throws exception when using the wrong context', function (string $action) { +it('returns error response when using the wrong context', function (string $action) { /** @var PdkEndpoint $endpoint */ $endpoint = Pdk::get(PdkEndpoint::class); $response = $endpoint->call($action, PdkEndpoint::CONTEXT_FRONTEND); @@ -158,18 +209,82 @@ function testEndpoint(string $action, string $context): void return; } + $responseContent = json_decode($response->getContent(), true); expect($response->getStatusCode()) ->toBe(Response::HTTP_UNPROCESSABLE_ENTITY) - ->and(json_decode($response->getContent(), true)) + ->and($responseContent['message']) + ->toBe("Action \"$action\" does not exist."); +})->with('backend actions'); + +it('returns error response on api exception', function () { + mockPdkProperties([FetchOrdersAction::class => get(MockApiExceptionAction::class)]); + + /** @var PdkEndpoint $endpoint */ + $endpoint = Pdk::get(PdkEndpoint::class); + $response = $endpoint->call(PdkBackendActions::FETCH_ORDERS, PdkEndpoint::CONTEXT_BACKEND); + + $responseContent = json_decode($response->getContent(), true); + + expect($response) + ->getStatusCode() + ->toBe(Response::HTTP_BAD_REQUEST) + ->and($responseContent) ->toBe([ - 'message' => "Action \"$action\" does not exist.", + 'message' => 'Request failed. Status code: 400. Message: boom', + 'request_id' => '12345', + 'errors' => [ + [ + 'code' => 24920, + 'message' => 'Something went wrong', + ], + [ + 'code' => 74892, + 'message' => 'Something else also went wrong', + ], + ], + ]); +}); + +it('returns error response on unknown exception', function () { + mockPdkProperties([FetchOrdersAction::class => get(MockExceptionAction::class)]); + + /** @var PdkEndpoint $endpoint */ + $endpoint = Pdk::get(PdkEndpoint::class); + $response = $endpoint->call(PdkBackendActions::FETCH_ORDERS, PdkEndpoint::CONTEXT_BACKEND); + + $responseContent = json_decode($response->getContent(), true); + + // Check if the file and line are set. + expect(Arr::get($responseContent, 'errors.0.file')) + ->toMatch('/\.php$/') + ->and(Arr::get($responseContent, 'errors.0.line')) + ->toBeInt() + ->and(Arr::get($responseContent, 'errors.0.trace')) + ->not->toBeEmpty(); + + // Remove trace properties before comparing as they are not static. + Arr::forget($responseContent, 'errors.0.trace'); + Arr::forget($responseContent, 'errors.0.file'); + Arr::forget($responseContent, 'errors.0.line'); + Arr::forget($responseContent, 'errors.1.trace'); + Arr::forget($responseContent, 'errors.1.file'); + Arr::forget($responseContent, 'errors.1.line'); + + expect($response) + ->getStatusCode() + ->toBe(Response::HTTP_BAD_REQUEST) + ->and($responseContent) + ->toBe([ + 'message' => 'Something went terribly wrong', 'errors' => [ [ - 'status' => 422, - 'code' => 0, - 'message' => "Action \"$action\" does not exist.", - 'trace' => 'Enable development mode to see stack trace.', + 'code' => 5, + 'message' => 'Something went terribly wrong', + ], + [ + 'code' => 1, + 'message' => 'Previous exception', ], ], ]); -})->with('backendActions'); +});