diff --git a/README.md b/README.md index bfba6a2..316e3b5 100644 --- a/README.md +++ b/README.md @@ -18,11 +18,13 @@ Provides a PSR-15 middleware that records every inbound HTTP exchange. Before invoking the next handler, the middleware logs the request method, URI, query parameters, and parsed body. After the handler runs, it logs the -response status code, decoded JSON body when present, and the elapsed duration in milliseconds. Successful -responses are logged at `info` level. Responses in the 4xx/5xx range are logged at `error` level. Chosen paths can be -left out of the log entirely, or logged only when their response is an error, so health checks and routes called on -a schedule do not bury the entries that matter. A body longer than 2048 bytes is logged as an excerpt that fits within -that limit, so a single entry stays well under the line length a log driver accepts. +response status code, decoded JSON body when present, and the elapsed duration in milliseconds. Responses in the +5xx range are logged at `error` level, responses in the 4xx range at `warning` level, and every other response at +`info` level, so a client mistake (a wrong password, a failed validation, an unknown resource) does not reach the +alerts that watch the `error` level. Chosen paths can be left out of the log entirely, or logged only when their +response is an error, so health checks and routes called on a schedule do not bury the entries that matter. A body +longer than 2048 bytes is logged as an excerpt that fits within that limit, so a single entry stays well under the +line length a log driver accepts. Duration is measured through a `TinyBlocks\Time\MonotonicClock` and a `Stopwatch`, so the reading is unaffected by wall-clock adjustments. When the request carries a correlation identifier (under the `correlationId` diff --git a/src/Internal/LogResponse.php b/src/Internal/LogResponse.php index 5141187..09cc99d 100644 --- a/src/Internal/LogResponse.php +++ b/src/Internal/LogResponse.php @@ -45,9 +45,10 @@ public function isError(): bool public function writeTo(LoggerInterface $logger): void { - match ($this->isError()) { - true => $logger->error('response', $this->toContext()), - false => $logger->info('response', $this->toContext()) + match (true) { + !$this->isError() => $logger->info('response', $this->toContext()), + $this->statusCode < Code::INTERNAL_SERVER_ERROR->value => $logger->warning('response', $this->toContext()), + default => $logger->error('response', $this->toContext()) }; } diff --git a/tests/Unit/LogMiddlewareTest.php b/tests/Unit/LogMiddlewareTest.php index 0532f05..9c4997d 100644 --- a/tests/Unit/LogMiddlewareTest.php +++ b/tests/Unit/LogMiddlewareTest.php @@ -366,42 +366,6 @@ public function testLogsWithCorrelationIdWhenPresent(): void /** @Then the correlation ID is present in each log call context (verified by mock expectations) */ } - public function testLogsErrorLevelOnClientErrorResponse(): void - { - /** @Given a POST request */ - $request = new ServerRequest('POST', '/users'); - - /** @And a handler that returns a 422 response */ - $handler = new CapturingHandler( - response: new Response(422, [], '{"error":"Unprocessable Entity"}') - ); - - /** @And a logger that expects info for request and error for response */ - $logger = $this->createMock(LoggerInterface::class); - - $logger->expects(self::once()) - ->method('info') - ->with('request'); - - $logger->expects(self::once()) - ->method('error') - ->with( - 'response', - self::callback(function (array $context): bool { - return $context['status_code'] === 422; - }) - ); - - /** @And a middleware configured with the logger */ - $middleware = LogMiddleware::create()->withLogger(logger: $logger)->build(); - - /** @When the middleware processes the request */ - $actual = $middleware->process($request, $handler); - - /** @Then the response should be returned with status 422 */ - self::assertSame(422, $actual->getStatusCode()); - } - public function testLogsErrorLevelOnServerErrorResponse(): void { /** @Given a DELETE request */ @@ -484,6 +448,44 @@ public function testBuilderThrowsWhenLoggerNotConfigured(): void $builder->build(); } + public function testLogsWarningLevelOnClientErrorResponse(): void + { + /** @Given a POST request */ + $request = new ServerRequest('POST', '/users'); + + /** @And a handler that returns a 422 response */ + $handler = new CapturingHandler( + response: new Response(422, [], '{"error":"Unprocessable Entity"}') + ); + + /** @And a logger that expects info for request, warning for response, and no error */ + $logger = $this->createMock(LoggerInterface::class); + + $logger->expects(self::once()) + ->method('info') + ->with('request'); + + $logger->expects(self::once()) + ->method('warning') + ->with( + 'response', + self::callback(function (array $context): bool { + return $context['status_code'] === 422; + }) + ); + + $logger->expects(self::never())->method('error'); + + /** @And a middleware configured with the logger */ + $middleware = LogMiddleware::create()->withLogger(logger: $logger)->build(); + + /** @When the middleware processes the request */ + $actual = $middleware->process($request, $handler); + + /** @Then the response should be returned with status 422 */ + self::assertSame(422, $actual->getStatusCode()); + } + #[DataProvider('anyStatusDataProvider')] public function testIgnoredPathWhenProcessedThenNothingIsLogged(int $statusCode): void { @@ -1057,6 +1059,30 @@ public function testFailureOnlyPathWhenCorrelationIdIsPresentThenEntriesCarryIt( ); } + #[DataProvider('responseLevelDataProvider')] + public function testResponseWhenStatusCodeIsInRangeThenLoggedAtLevelOfThatRange( + int $statusCode, + string $level + ): void { + /** @Given a GET request */ + $request = new ServerRequest('GET', '/v1/orders'); + + /** @And a handler that answers with the status code of the data set */ + $handler = new CapturingHandler(response: new Response($statusCode)); + + /** @And a logger that captures every entry */ + $logger = new CapturingLogger(); + + /** @And a middleware configured with the logger */ + $middleware = LogMiddleware::create()->withLogger(logger: $logger)->build(); + + /** @When the middleware processes the request */ + $middleware->process($request, $handler); + + /** @Then the request entry is logged at info and the response entry at the level of the status range */ + self::assertSame(['info', $level], array_column($logger->entries(), 'level')); + } + public function testBuildWhenOnlyClockAndLoggerAreGivenThenEveryExchangeIsLogged(): void { /** @Given a health check request */ @@ -1157,8 +1183,10 @@ public function testUnlistedPathWhenPathsAreConfiguredThenExchangeIsLoggedAsBefo } #[DataProvider('errorStatusDataProvider')] - public function testFailureOnlyPathWhenResponseFailsThenRequestAndResponseAreLogged(int $statusCode): void - { + public function testFailureOnlyPathWhenResponseFailsThenRequestAndResponseAreLogged( + int $statusCode, + string $level + ): void { /** @Given a request to a periodic sweep route carrying query parameters and a body */ $request = new ServerRequest('POST', '/v1/outbox/dispatches?batch=10') ->withQueryParams(['batch' => '10']) @@ -1180,7 +1208,7 @@ public function testFailureOnlyPathWhenResponseFailsThenRequestAndResponseAreLog /** @When the middleware processes the request */ $middleware->process($request, $handler); - /** @Then the request entry and the response entry are written with the context any other path gets */ + /** @Then the request entry and the response entry are written with the context and level any other path gets */ self::assertSame( [ [ @@ -1194,7 +1222,7 @@ public function testFailureOnlyPathWhenResponseFailsThenRequestAndResponseAreLog ] ], [ - 'level' => 'error', + 'level' => $level, 'message' => 'response', 'context' => [ 'method' => 'POST', @@ -1304,11 +1332,12 @@ public static function anyStatusDataProvider(): array public static function errorStatusDataProvider(): array { return [ - 'Bad request' => [400], - 'Not found' => [404], - 'Unprocessable entity' => [422], - 'Internal server error' => [500], - 'Service unavailable' => [503] + 'Bad request' => [400, 'warning'], + 'Not found' => [404, 'warning'], + 'Unprocessable entity' => [422, 'warning'], + 'Highest client error' => [499, 'warning'], + 'Internal server error' => [500, 'error'], + 'Service unavailable' => [503, 'error'] ]; } @@ -1401,13 +1430,31 @@ public static function overLimitBodyDataProvider(): array ]; } + public static function responseLevelDataProvider(): array + { + return [ + 'OK' => [200, 'info'], + 'Found' => [302, 'info'], + 'Highest redirection' => [399, 'info'], + 'Bad request' => [400, 'warning'], + 'Unauthorized' => [401, 'warning'], + 'Not found' => [404, 'warning'], + 'Unprocessable entity' => [422, 'warning'], + 'Highest client error' => [499, 'warning'], + 'Internal server error' => [500, 'error'], + 'Service unavailable' => [503, 'error'], + 'Network authentication needed' => [511, 'error'] + ]; + } + public static function nonErrorStatusDataProvider(): array { return [ - 'OK' => [200], - 'Created' => [201], - 'No content' => [204], - 'Found' => [302] + 'OK' => [200], + 'Created' => [201], + 'No content' => [204], + 'Found' => [302], + 'Highest redirection' => [399] ]; } @@ -1415,6 +1462,7 @@ public static function statusAndLevelDataProvider(): array { return [ 'Successful response' => [200, 'info'], + 'Client error' => [422, 'warning'], 'Server error' => [500, 'error'] ]; }