Skip to content

Log client error responses at warning level. #12

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
gustavofreze merged 1 commit into from
Nov 10, 2026
Merged

Log client error responses at warning level. #12

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
12 changes: 7 additions & 5 deletions README.md
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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`
Expand Down
7 changes: 4 additions & 3 deletions src/Internal/LogResponse.php
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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())
};
}

Expand Down
146 changes: 97 additions & 49 deletions tests/Unit/LogMiddlewareTest.php
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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 */
Expand Down Expand Up @@ -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
{
Expand Down Expand Up @@ -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 */
Expand Down Expand Up @@ -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'])
Expand All @@ -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(
[
[
Expand All @@ -1194,7 +1222,7 @@ public function testFailureOnlyPathWhenResponseFailsThenRequestAndResponseAreLog
]
],
[
'level' => 'error',
'level' => $level,
'message' => 'response',
'context' => [
'method' => 'POST',
Expand Down Expand Up @@ -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']
];
}

Expand Down Expand Up @@ -1401,20 +1430,39 @@ 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]
];
}

public static function statusAndLevelDataProvider(): array
{
return [
'Successful response' => [200, 'info'],
'Client error' => [422, 'warning'],
'Server error' => [500, 'error']
];
}
Expand Down