diff --git a/README.md b/README.md index aa156b9..bfba6a2 100644 --- a/README.md +++ b/README.md @@ -10,6 +10,7 @@ + [Customizing the clock](#customizing-the-clock) + [Ignoring paths](#ignoring-paths) + [Logging paths only on failure](#logging-paths-only-on-failure) + + [Limiting logged bodies](#limiting-logged-bodies) * [License](#license) * [Contributing](#contributing) @@ -20,7 +21,8 @@ middleware logs the request method, URI, query parameters, and parsed body. Afte 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 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` @@ -166,6 +168,51 @@ $middleware = LogMiddleware::create() ->build(); ``` +### Limiting logged bodies + +Caps the size of every request and response body written to the log. The size of a body is the length in bytes of its +JSON encoding, written the way a JSON logger writes it (unescaped slashes and unescaped UTF-8). A body within the limit +is logged whole. A longer body is logged as an excerpt that fits within the limit, and the entry gains +`body_truncated_from_bytes`, the size of the whole body. Without `withBodyLimit` the limit is 2048 bytes. + +The excerpt is the body read in document order until the limit is reached: + +| Part of the body | In the excerpt | +|------------------------------------|----------------------------------------------------| +| Fields and elements that fit | Kept as they are, with their field names. | +| The string where the limit falls | Cut on a whole UTF-8 character and ended with `…`. | +| The object or array where it falls | Read the same way, one level down. | +| Everything after the limit | Left out. | + +The excerpt stays a JSON object or array, never a string holding broken JSON, so the entry remains valid JSON and a +logger that redacts fields by name, such as the redactions of +[tiny-blocks/logger](https://github.com/tiny-blocks/logger), still finds and masks them in the excerpt. + +```php +withLogger(logger: $logger) + ->withBodyLimit(bytes: 4096) + ->build(); + +# A response body of 18342 bytes is then logged as, for example: +# "body":{"version":"3","text":"Ao aceitar estes termos…"},"body_truncated_from_bytes":18342 +``` + +A limit of zero logs the size of every body and none of its content. A negative limit raises `BodyLimitOutOfRange` +when the middleware is built. + +The default leaves room for the rest of the entry. Docker's `awslogs` driver splits a line longer than 16 KB into +fragments that are no longer valid JSON, and an entry carries one body next to the method, the URI, the query +parameters and the correlation identifier. 2048 bytes keeps the whole entry well under that line length, even when a +logger escapes every non-ASCII character and the body triples in size. + ## License Http Logging is licensed under [MIT](LICENSE). diff --git a/phpstan.neon.dist b/phpstan.neon.dist index 5b14f49..27bc047 100644 --- a/phpstan.neon.dist +++ b/phpstan.neon.dist @@ -17,6 +17,10 @@ parameters: # carry its value type there. - identifier: missingType.iterableValue path: src/Internal/Paths.php + # PHPDoc is prohibited inside src/Internal/; the decoded body and the excerpt cut + # from it are arbitrary JSON values, so their iterable value types cannot be expressed. + - identifier: missingType.iterableValue + path: src/Internal/BodyLimit.php # The request context returned by LogRequest::toContext() is typed as `array`, so # PHPStan cannot infer the shape consumed by the LogResponse factory. - identifier: argument.type @@ -31,4 +35,5 @@ parameters: paths: - tests/Unit/CapturingLogger.php - tests/Unit/LogMiddlewareTest.php + - tests/Unit/RedactingLogger.php reportUnmatchedIgnoredErrors: true diff --git a/src/Exceptions/BodyLimitOutOfRange.php b/src/Exceptions/BodyLimitOutOfRange.php new file mode 100644 index 0000000..d0f9560 --- /dev/null +++ b/src/Exceptions/BodyLimitOutOfRange.php @@ -0,0 +1,11 @@ + $budget) { + break; + } + + $characters[] = $character; + $budget -= $size; + } + + $template = '%s%s'; + + return sprintf($template, implode('', $characters), self::ELLIPSIS); + } + + public static function from(?int $bytes): BodyLimit + { + $limit = ($bytes ?? self::DEFAULT_BYTES); + + if ($limit < 0) { + $template = 'Body limit must be zero or more bytes, got %d.'; + + throw new BodyLimitOutOfRange(message: sprintf($template, $limit)); + } + + return new BodyLimit(bytes: $limit); + } + + private static function closed(int|string $key, array $excerpt, array|string|null $fragment): array + { + return is_null($fragment) ? $excerpt : ($excerpt + [$key => $fragment]); + } + + private static function sizeOf(mixed $value): int + { + return strlen(json_encode($value, self::ENCODING_FLAGS)); + } + + private static function framingOf(int|string $key, bool $isList, bool $isFirst): int + { + $separator = $isFirst ? 0 : self::SEPARATOR_BYTES; + $name = $isList ? 0 : (BodyLimit::sizeOf(value: (string)$key) + self::SEPARATOR_BYTES); + + return ($separator + $name); + } + + public function contextOf(?array $body): array + { + if (empty($body)) { + return []; + } + + $size = BodyLimit::sizeOf(value: $body); + + if ($size <= $this->bytes) { + return ['body' => $body]; + } + + $excerpt = $this->excerptOf(budget: ($this->bytes - self::BRACKETS_BYTES), elements: $body); + + return ['body' => $excerpt, 'body_truncated_from_bytes' => $size]; + } + + private function excerptOf(int $budget, array $elements): array + { + $excerpt = []; + $isList = array_is_list($elements); + + foreach ($elements as $key => $element) { + $available = ($budget - BodyLimit::framingOf(key: $key, isList: $isList, isFirst: empty($excerpt))); + $size = BodyLimit::sizeOf(value: $element); + + if ($size > $available) { + $fragment = $this->fragmentOf(element: $element, available: $available); + + return BodyLimit::closed(key: $key, excerpt: $excerpt, fragment: $fragment); + } + + $excerpt[$key] = $element; + $budget = ($available - $size); + } + + return $excerpt; + } + + private function fragmentOf(mixed $element, int $available): array|string|null + { + if (is_array($element) && $available >= self::BRACKETS_BYTES) { + return $this->excerptOf(budget: ($available - self::BRACKETS_BYTES), elements: $element); + } + + if (is_string($element) && $available >= BodyLimit::sizeOf(value: self::ELLIPSIS)) { + return BodyLimit::cut(text: $element, available: $available); + } + + return null; + } +} diff --git a/src/Internal/FailureOnlyLogExchange.php b/src/Internal/FailureOnlyLogExchange.php index fe8accf..9d34db1 100644 --- a/src/Internal/FailureOnlyLogExchange.php +++ b/src/Internal/FailureOnlyLogExchange.php @@ -15,6 +15,7 @@ private function __construct( private LoggerInterface $logger, private LogRequest $request, + private BodyLimit $bodyLimit, private Stopwatch $stopwatch ) { } @@ -22,11 +23,13 @@ private function __construct( public static function start( MonotonicClock $clock, LoggerInterface $logger, - ServerRequestInterface $request + ServerRequestInterface $request, + BodyLimit $bodyLimit ): FailureOnlyLogExchange { return new FailureOnlyLogExchange( logger: $logger, - request: LogRequest::from(request: $request), + request: LogRequest::from(request: $request, bodyLimit: $bodyLimit), + bodyLimit: $bodyLimit, stopwatch: Stopwatch::start(clock: $clock) ); } @@ -36,7 +39,8 @@ public function complete(ResponseInterface $response): ResponseInterface $responseLog = LogResponse::from( elapsed: $this->stopwatch->elapsed(), request: $this->request, - response: $response + response: $response, + bodyLimit: $this->bodyLimit ); if (!$responseLog->isError()) { diff --git a/src/Internal/LogExchange.php b/src/Internal/LogExchange.php index 4e49ff9..49b9ccf 100644 --- a/src/Internal/LogExchange.php +++ b/src/Internal/LogExchange.php @@ -15,6 +15,7 @@ private function __construct( private LoggerInterface $logger, private LogRequest $request, + private BodyLimit $bodyLimit, private Stopwatch $stopwatch ) { } @@ -22,14 +23,16 @@ private function __construct( public static function start( MonotonicClock $clock, LoggerInterface $logger, - ServerRequestInterface $request + ServerRequestInterface $request, + BodyLimit $bodyLimit ): LogExchange { - $requestLog = LogRequest::from(request: $request); + $requestLog = LogRequest::from(request: $request, bodyLimit: $bodyLimit); $requestLog->writeTo(logger: $logger); return new LogExchange( logger: $logger, request: $requestLog, + bodyLimit: $bodyLimit, stopwatch: Stopwatch::start(clock: $clock) ); } @@ -39,7 +42,8 @@ public function complete(ResponseInterface $response): ResponseInterface LogResponse::from( elapsed: $this->stopwatch->elapsed(), request: $this->request, - response: $response + response: $response, + bodyLimit: $this->bodyLimit )->writeTo(logger: $this->logger); return $response; diff --git a/src/Internal/LogRequest.php b/src/Internal/LogRequest.php index 5c4d4f7..a1a28b8 100644 --- a/src/Internal/LogRequest.php +++ b/src/Internal/LogRequest.php @@ -12,13 +12,13 @@ { private function __construct( private string $uri, - private ?array $body, + private array $body, private string $method, private array $queryParameters ) { } - public static function from(ServerRequestInterface $request): LogRequest + public static function from(ServerRequestInterface $request, BodyLimit $bodyLimit): LogRequest { $typedRequest = Request::from(request: $request); $decodedRequest = $typedRequest->decode(); @@ -26,7 +26,7 @@ public static function from(ServerRequestInterface $request): LogRequest return new LogRequest( uri: $uri->toString(), - body: $decodedRequest->body()->toArray(), + body: $bodyLimit->contextOf(body: $decodedRequest->body()->toArray()), method: $typedRequest->method()->value, queryParameters: $uri->queryParameters()->toArray() ); @@ -48,10 +48,6 @@ public function toContext(): array $context['query_parameters'] = $this->queryParameters; } - if (!empty($this->body)) { - $context['body'] = $this->body; - } - - return $context; + return [...$context, ...$this->body]; } } diff --git a/src/Internal/LogResponse.php b/src/Internal/LogResponse.php index 0d6f38b..5141187 100644 --- a/src/Internal/LogResponse.php +++ b/src/Internal/LogResponse.php @@ -13,21 +13,25 @@ { private function __construct( private string $uri, - private ?array $body, + private array $body, private string $method, private Elapsed $elapsed, private int $statusCode ) { } - public static function from(Elapsed $elapsed, LogRequest $request, ResponseInterface $response): LogResponse - { + public static function from( + Elapsed $elapsed, + LogRequest $request, + ResponseInterface $response, + BodyLimit $bodyLimit + ): LogResponse { $context = $request->toContext(); $decodedBody = json_decode($response->getBody()->__toString(), true); return new LogResponse( uri: $context['uri'], - body: is_array($decodedBody) ? $decodedBody : null, + body: $bodyLimit->contextOf(body: is_array($decodedBody) ? $decodedBody : null), method: $context['method'], elapsed: $elapsed, statusCode: $response->getStatusCode() @@ -56,10 +60,6 @@ private function toContext(): array 'duration_ms' => $this->elapsed->toMilliseconds() ]; - if (!empty($this->body)) { - $context['body'] = $this->body; - } - - return $context; + return [...$context, ...$this->body]; } } diff --git a/src/LogMiddleware.php b/src/LogMiddleware.php index 09565be..12dbd00 100644 --- a/src/LogMiddleware.php +++ b/src/LogMiddleware.php @@ -12,6 +12,8 @@ use TinyBlocks\Http\CorrelationId\CorrelatedLogger; use TinyBlocks\Http\CorrelationId\CorrelationId; use TinyBlocks\Http\CorrelationId\CorrelationIdMiddleware; +use TinyBlocks\Http\Logging\Exceptions\BodyLimitOutOfRange; +use TinyBlocks\Http\Logging\Internal\BodyLimit; use TinyBlocks\Http\Logging\Internal\FailureOnlyLogExchange; use TinyBlocks\Http\Logging\Internal\LogExchange; use TinyBlocks\Http\Logging\Internal\Paths; @@ -26,32 +28,42 @@ private function __construct( private MonotonicClock $clock, private LoggerInterface $logger, + private BodyLimit $bodyLimit, private Paths $ignoredPaths, private Paths $failureOnlyPaths ) { } /** - * Builds a LogMiddleware from a monotonic clock, a logger, and optional path filters. + * Builds a LogMiddleware from a monotonic clock, a logger, an optional body limit, and optional path filters. * *

Paths are compared by exact string equality with the request URI path. A path present in both lists is * never logged.

* + *

A request or response body whose JSON encoding is longer than the body limit is logged as an excerpt that + * fits within the limit, together with body_truncated_from_bytes, the size of the whole body. The + * excerpt is still a JSON object or array and keeps its field names, so a logger that redacts fields by name + * keeps redacting them.

+ * * @param MonotonicClock $clock The monotonic clock used to measure request duration. * @param LoggerInterface $logger The logger to use for request and response logging. + * @param int|null $bodyLimit The largest body, in bytes of its JSON encoding, logged whole, or null for 2048. * @param array $ignoredPaths The request paths that are never logged. * @param array $failureOnlyPaths The request paths that are logged only when the response is an error. * @return LogMiddleware The configured middleware instance. + * @throws BodyLimitOutOfRange If the body limit is negative. */ public static function build( MonotonicClock $clock, LoggerInterface $logger, + ?int $bodyLimit = null, array $ignoredPaths = [], array $failureOnlyPaths = [] ): LogMiddleware { return new LogMiddleware( clock: $clock, logger: $logger, + bodyLimit: BodyLimit::from(bytes: $bodyLimit), ignoredPaths: Paths::from(...$ignoredPaths), failureOnlyPaths: Paths::from(...$failureOnlyPaths) ); @@ -81,8 +93,18 @@ public function process(ServerRequestInterface $request, RequestHandlerInterface : $this->logger; $exchange = $this->failureOnlyPaths->contains(path: $path) - ? FailureOnlyLogExchange::start(clock: $this->clock, logger: $logger, request: $request) - : LogExchange::start(clock: $this->clock, logger: $logger, request: $request); + ? FailureOnlyLogExchange::start( + clock: $this->clock, + logger: $logger, + request: $request, + bodyLimit: $this->bodyLimit + ) + : LogExchange::start( + clock: $this->clock, + logger: $logger, + request: $request, + bodyLimit: $this->bodyLimit + ); $response = $handler->handle($request); diff --git a/src/LogMiddlewareBuilder.php b/src/LogMiddlewareBuilder.php index 0b4d69f..fc6d2d7 100644 --- a/src/LogMiddlewareBuilder.php +++ b/src/LogMiddlewareBuilder.php @@ -5,17 +5,20 @@ namespace TinyBlocks\Http\Logging; use Psr\Log\LoggerInterface; +use TinyBlocks\Http\Logging\Exceptions\BodyLimitOutOfRange; use TinyBlocks\Http\Logging\Exceptions\LoggerNotConfigured; use TinyBlocks\Time\MonotonicClock; use TinyBlocks\Time\SystemMonotonicClock; /** - * Fluent builder that assembles a LogMiddleware with an optional custom monotonic clock and optional path filters. + * Fluent builder that assembles a LogMiddleware with an optional custom monotonic clock, an optional body limit, + * and optional path filters. */ final class LogMiddlewareBuilder { private MonotonicClock $clock; private ?LoggerInterface $logger = null; + private ?int $bodyLimit = null; /** @var array */ private array $ignoredPaths = []; @@ -29,10 +32,11 @@ public function __construct() } /** - * Builds a LogMiddleware from the configured logger, monotonic clock, and path filters. + * Builds a LogMiddleware from the configured logger, monotonic clock, body limit, and path filters. * * @return LogMiddleware The configured middleware instance. * @throws LoggerNotConfigured If no logger was configured. + * @throws BodyLimitOutOfRange If the configured body limit is negative. */ public function build(): LogMiddleware { @@ -43,6 +47,7 @@ public function build(): LogMiddleware return LogMiddleware::build( clock: $this->clock, logger: $this->logger, + bodyLimit: $this->bodyLimit, ignoredPaths: $this->ignoredPaths, failureOnlyPaths: $this->failureOnlyPaths ); @@ -72,6 +77,26 @@ public function withLogger(LoggerInterface $logger): LogMiddlewareBuilder return $this; } + /** + * Sets the largest request or response body logged whole and returns the builder. + * + *

The size of a body is the length in bytes of its JSON encoding, written the way a JSON logger writes it + * (unescaped slashes and unescaped UTF-8). A body within the limit is logged whole, exactly as before. A longer + * body is logged as an excerpt that fits within the limit, together with body_truncated_from_bytes, + * the size of the whole body. The excerpt is the body read in document order up to the limit: it stays a JSON + * object or array with its field names, a string cut short ends in … on a whole UTF-8 character, + * and the fields past the limit are left out. Without this call the limit is 2048 bytes. A limit of zero logs + * the size of every body and none of its content.

+ * + * @param int $bytes The largest body, in bytes of its JSON encoding, that is logged whole. + * @return LogMiddlewareBuilder The builder instance for fluent configuration. + */ + public function withBodyLimit(int $bytes): LogMiddlewareBuilder + { + $this->bodyLimit = $bytes; + return $this; + } + /** * Sets the request paths that are never logged and returns the builder. * diff --git a/tests/Unit/LogMiddlewareTest.php b/tests/Unit/LogMiddlewareTest.php index 17f8498..0532f05 100644 --- a/tests/Unit/LogMiddlewareTest.php +++ b/tests/Unit/LogMiddlewareTest.php @@ -10,6 +10,7 @@ use PHPUnit\Framework\TestCase; use Psr\Log\LoggerInterface; use TinyBlocks\Http\CorrelationId\CorrelationId; +use TinyBlocks\Http\Logging\Exceptions\BodyLimitOutOfRange; use TinyBlocks\Http\Logging\Exceptions\LoggerNotConfigured; use TinyBlocks\Http\Logging\LogMiddleware; @@ -539,6 +540,41 @@ public function testLogsWithBaseLoggerWhenCorrelationIdIsAbsent(): void /** @Then the base logger should have been used directly (verified by mock expectations) */ } + public function testBodyLimitWhenZeroThenOnlyTheBodySizeIsLogged(): void + { + /** @Given a GET request */ + $request = new ServerRequest('GET', '/documents/1'); + + /** @And a handler that returns a response whose JSON body is 8 bytes long */ + $handler = new CapturingHandler(response: new Response(200, [], '{"id":1}')); + + /** @And a logger that captures every entry */ + $logger = new CapturingLogger(); + + /** @And a middleware with a deterministic clock whose body limit is zero */ + $middleware = LogMiddleware::create() + ->withClock(clock: new ClockFake(initial: 0, increment: 2_000_000)) + ->withLogger(logger: $logger) + ->withBodyLimit(bytes: 0) + ->build(); + + /** @When the middleware processes the request */ + $middleware->process($request, $handler); + + /** @Then the response entry keeps no part of the body and carries the size of the whole body */ + self::assertSame( + [ + 'method' => 'GET', + 'uri' => '/documents/1', + 'status_code' => 200, + 'duration_ms' => 2.0, + 'body' => [], + 'body_truncated_from_bytes' => 8 + ], + $logger->entries()[1]['context'] + ); + } + public function testLogsRequestContextAlwaysContainsMethodAndUri(): void { /** @Given a PUT request to a specific URI */ @@ -570,6 +606,77 @@ public function testLogsRequestContextAlwaysContainsMethodAndUri(): void self::assertSame('/orders/42', $capturedContext['uri']); } + public function testResponseBodyWhenAtDefaultLimitThenLoggedWhole(): void + { + /** @Given a GET request */ + $request = new ServerRequest('GET', '/documents/1'); + + /** @And a handler that returns a response whose JSON body is 2048 bytes long, the default limit */ + $handler = new CapturingHandler( + response: new Response(200, [], (string) json_encode(['text' => str_repeat('a', 2037)])) + ); + + /** @And a logger that captures every entry */ + $logger = new CapturingLogger(); + + /** @And a middleware with a deterministic clock and the default body limit */ + $middleware = LogMiddleware::create() + ->withClock(clock: new ClockFake(initial: 0, increment: 2_000_000)) + ->withLogger(logger: $logger) + ->build(); + + /** @When the middleware processes the request */ + $middleware->process($request, $handler); + + /** @Then the response entry carries the whole body and no truncation marker */ + self::assertSame( + [ + 'method' => 'GET', + 'uri' => '/documents/1', + 'status_code' => 200, + 'duration_ms' => 2.0, + 'body' => ['text' => str_repeat('a', 2037)] + ], + $logger->entries()[1]['context'] + ); + } + + public function testResponseBodyWhenExactlyAtLimitThenLoggedWhole(): void + { + /** @Given a GET request */ + $request = new ServerRequest('GET', '/documents/1'); + + /** @And a handler that returns a response whose JSON body is 44 bytes long */ + $handler = new CapturingHandler( + response: new Response(200, [], '{"id":7,"text":"abcdefghijklmnopqrstuvwxyz"}') + ); + + /** @And a logger that captures every entry */ + $logger = new CapturingLogger(); + + /** @And a middleware with a deterministic clock whose body limit is 44 bytes */ + $middleware = LogMiddleware::create() + ->withClock(clock: new ClockFake(initial: 0, increment: 2_000_000)) + ->withLogger(logger: $logger) + ->withBodyLimit(bytes: 44) + ->build(); + + /** @When the middleware processes the request */ + $middleware->process($request, $handler); + + /** @Then the response entry carries the whole body and no truncation marker */ + self::assertSame( + [ + 'method' => 'GET', + 'uri' => '/documents/1', + 'status_code' => 200, + 'duration_ms' => 2.0, + 'body' => ['id' => 7, 'text' => 'abcdefghijklmnopqrstuvwxyz'] + ], + $logger->entries()[1]['context'] + ); + } + public function testDurationIsComputedWithTwoDecimalPlacePrecision(): void { /** @Given a clock that advances by 1,267,000 nanoseconds per reading */ @@ -606,6 +713,39 @@ public function testDurationIsComputedWithTwoDecimalPlacePrecision(): void self::assertSame(1.27, $capturedContext['duration_ms']); } + public function testRequestBodyWhenOverLimitThenTruncatedWithItsSize(): void + { + /** @Given a POST request whose parsed body is 37 bytes long once encoded */ + $request = new ServerRequest('POST', '/notes') + ->withParsedBody(['note' => 'abcdefghijklmnopqrstuvwxyz']); + + /** @And a handler that returns a 201 response */ + $handler = new CapturingHandler(response: new Response(201)); + + /** @And a logger that captures every entry */ + $logger = new CapturingLogger(); + + /** @And a middleware whose body limit is 20 bytes */ + $middleware = LogMiddleware::create() + ->withLogger(logger: $logger) + ->withBodyLimit(bytes: 20) + ->build(); + + /** @When the middleware processes the request */ + $middleware->process($request, $handler); + + /** @Then the request entry carries an excerpt within 20 bytes and the size of the whole body */ + self::assertSame( + [ + 'method' => 'POST', + 'uri' => '/notes', + 'body' => ['note' => 'abcdef…'], + 'body_truncated_from_bytes' => 37 + ], + $logger->entries()[0]['context'] + ); + } + public function testLogsResponseBodyStreamRemainsReadableAfterLogging(): void { /** @Given a GET request */ @@ -630,6 +770,21 @@ public function testLogsResponseBodyStreamRemainsReadableAfterLogging(): void self::assertSame($bodyContent, $actual->getBody()->__toString()); } + public function testBuildWhenBodyLimitIsNegativeThenBodyLimitOutOfRange(): void + { + /** @Given a builder configured with a logger and a negative body limit */ + $builder = LogMiddleware::create() + ->withLogger(logger: new CapturingLogger()) + ->withBodyLimit(bytes: -1); + + /** @Then an exception indicating the body limit is out of range should be thrown */ + $this->expectException(BodyLimitOutOfRange::class); + $this->expectExceptionMessage('Body limit must be zero or more bytes, got -1.'); + + /** @When building the middleware */ + $builder->build(); + } + public function testBuilderWhenNoPathsAreGivenThenEveryExchangeIsLogged(): void { /** @Given a health check request */ @@ -680,6 +835,112 @@ public function testPathInBothListsWhenResponseFailsThenNothingIsLogged(): void self::assertSame([], $logger->entries()); } + public function testRequestBodyWhenNotValidUtf8ThenLoggedWithoutFailing(): void + { + /** @Given a POST request whose parsed body holds bytes that are not valid UTF-8 */ + $request = new ServerRequest('POST', '/notes')->withParsedBody(['note' => "\xB1\x31"]); + + /** @And a handler that returns a 201 response */ + $handler = new CapturingHandler(response: new Response(201)); + + /** @And a logger that captures every entry */ + $logger = new CapturingLogger(); + + /** @And a middleware with the default body limit */ + $middleware = LogMiddleware::create()->withLogger(logger: $logger)->build(); + + /** @When the middleware processes the request */ + $middleware->process($request, $handler); + + /** @Then the request entry carries the body untouched */ + self::assertSame( + ['method' => 'POST', 'uri' => '/notes', 'body' => ['note' => "\xB1\x31"]], + $logger->entries()[0]['context'] + ); + } + + #[DataProvider('overLimitBodyDataProvider')] + public function testResponseBodyWhenOverLimitThenExcerptFitsWithinLimit( + int $limit, + array $body, + array $excerpt, + int $bytes + ): void { + /** @Given a GET request */ + $request = new ServerRequest('GET', '/documents/1'); + + /** @And a handler that returns a response whose JSON body is longer than the limit of the data set */ + $handler = new CapturingHandler(response: new Response(200, [], (string) json_encode($body))); + + /** @And a logger that captures every entry */ + $logger = new CapturingLogger(); + + /** @And a middleware with a deterministic clock and the body limit of the data set */ + $middleware = LogMiddleware::create() + ->withClock(clock: new ClockFake(initial: 0, increment: 2_000_000)) + ->withLogger(logger: $logger) + ->withBodyLimit(bytes: $limit) + ->build(); + + /** @When the middleware processes the request */ + $middleware->process($request, $handler); + + /** @Then the response entry carries the excerpt of the data set and the size of the whole body */ + self::assertSame( + [ + 'method' => 'GET', + 'uri' => '/documents/1', + 'status_code' => 200, + 'duration_ms' => 2.0, + 'body' => $excerpt, + 'body_truncated_from_bytes' => $bytes + ], + $logger->entries()[1]['context'] + ); + + /** @And the excerpt, encoded the way a JSON logger writes it, stays within the limit */ + self::assertLessThanOrEqual( + $limit, + strlen((string) json_encode($excerpt, (JSON_UNESCAPED_UNICODE | JSON_UNESCAPED_SLASHES))) + ); + } + + public function testResponseBodyWhenOneByteOverDefaultLimitThenTruncated(): void + { + /** @Given a GET request */ + $request = new ServerRequest('GET', '/documents/1'); + + /** @And a handler that returns a response whose JSON body is 2049 bytes long, one over the default limit */ + $handler = new CapturingHandler( + response: new Response(200, [], (string) json_encode(['text' => str_repeat('a', 2038)])) + ); + + /** @And a logger that captures every entry */ + $logger = new CapturingLogger(); + + /** @And a middleware with a deterministic clock and the default body limit */ + $middleware = LogMiddleware::create() + ->withClock(clock: new ClockFake(initial: 0, increment: 2_000_000)) + ->withLogger(logger: $logger) + ->build(); + + /** @When the middleware processes the request */ + $middleware->process($request, $handler); + + /** @Then the response entry carries an excerpt cut to 2048 bytes and the size of the whole body */ + self::assertSame( + [ + 'method' => 'GET', + 'uri' => '/documents/1', + 'status_code' => 200, + 'duration_ms' => 2.0, + 'body' => ['text' => implode('', [str_repeat('a', 2034), '…'])], + 'body_truncated_from_bytes' => 2049 + ], + $logger->entries()[1]['context'] + ); + } + #[DataProvider('nonErrorStatusDataProvider')] public function testFailureOnlyPathWhenResponseSucceedsThenNothingIsLogged(int $statusCode): void { @@ -705,6 +966,43 @@ public function testFailureOnlyPathWhenResponseSucceedsThenNothingIsLogged(int $ self::assertSame([], $logger->entries()); } + public function testTruncatedBodyWhenLoggerRedactsFieldsThenExcerptIsRedacted(): void + { + /** @Given a GET request */ + $request = new ServerRequest('GET', '/legal-acceptances/1'); + + /** @And a handler that returns a response with an email and a text, 64 bytes long in all */ + $handler = new CapturingHandler( + response: new Response(200, [], '{"email":"john@example.com","text":"abcdefghijklmnopqrstuvwxyz"}') + ); + + /** @And a logger that masks every email field before writing the entry */ + $logger = new RedactingLogger(); + + /** @And a middleware with a deterministic clock whose body limit is 50 bytes */ + $middleware = LogMiddleware::create() + ->withClock(clock: new ClockFake(initial: 0, increment: 2_000_000)) + ->withLogger(logger: $logger) + ->withBodyLimit(bytes: 50) + ->build(); + + /** @When the middleware processes the request */ + $middleware->process($request, $handler); + + /** @Then the excerpt keeps its fields, so the email is masked by the logger and the text is cut */ + self::assertSame( + [ + 'method' => 'GET', + 'uri' => '/legal-acceptances/1', + 'status_code' => 200, + 'duration_ms' => 2.0, + 'body' => ['email' => '***', 'text' => 'abcdefghi…'], + 'body_truncated_from_bytes' => 64 + ], + $logger->entries()[1]['context'] + ); + } + public function testFailureOnlyPathWhenCorrelationIdIsPresentThenEntriesCarryIt(): void { /** @Given a correlation ID */ @@ -1025,6 +1323,84 @@ public static function partialMatchDataProvider(): array ]; } + public static function overLimitBodyDataProvider(): array + { + return [ + 'String cut after a field that fits' => [ + 'limit' => 30, + 'body' => ['id' => 7, 'text' => 'abcdefghijklmnopqrstuvwxyz'], + 'excerpt' => ['id' => 7, 'text' => 'abcdefghi…'], + 'bytes' => 44 + ], + 'List element that fits exactly' => [ + 'limit' => 17, + 'body' => [1000000, 2000000, 3000000], + 'excerpt' => [1000000, 2000000], + 'bytes' => 25 + ], + 'Number that does not fit' => [ + 'limit' => 23, + 'body' => [1000000, 2000000, 3000000], + 'excerpt' => [1000000, 2000000], + 'bytes' => 25 + ], + 'Nested object cut inside' => [ + 'limit' => 25, + 'body' => ['data' => ['name' => 'abcdefghij']], + 'excerpt' => ['data' => ['name' => 'ab…']], + 'bytes' => 30 + ], + 'Nested object with room for its brackets only' => [ + 'limit' => 18, + 'body' => ['a' => 'xyz', 'b' => ['c' => 'd']], + 'excerpt' => ['a' => 'xyz', 'b' => []], + 'bytes' => 25 + ], + 'String with room for the ellipsis only' => [ + 'limit' => 21, + 'body' => ['a' => 'xyz', 'b' => 'long text'], + 'excerpt' => ['a' => 'xyz', 'b' => '…'], + 'bytes' => 27 + ], + 'String without room for the ellipsis' => [ + 'limit' => 20, + 'body' => ['a' => 'xyz', 'b' => 'long text'], + 'excerpt' => ['a' => 'xyz'], + 'bytes' => 27 + ], + 'Numeric keys counted as quoted names' => [ + 'limit' => 22, + 'body' => ['10' => 'abcdef', '20' => 'ghijkl'], + 'excerpt' => [10 => 'abcdef'], + 'bytes' => 29 + ], + 'Two-byte character kept whole' => [ + 'limit' => 18, + 'body' => ['text' => 'aaéaaaa'], + 'excerpt' => ['text' => 'aaé…'], + 'bytes' => 19 + ], + 'Two-byte character left out whole' => [ + 'limit' => 17, + 'body' => ['text' => 'aaéaaaa'], + 'excerpt' => ['text' => 'aa…'], + 'bytes' => 19 + ], + 'Four-byte character left out whole' => [ + 'limit' => 19, + 'body' => ['text' => 'ab😀cdef'], + 'excerpt' => ['text' => 'ab…'], + 'bytes' => 21 + ], + 'Escaped characters counted at encoded size' => [ + 'limit' => 18, + 'body' => ['text' => '"q"rstuvwxyz'], + 'excerpt' => ['text' => '"q…'], + 'bytes' => 25 + ] + ]; + } + public static function nonErrorStatusDataProvider(): array { return [ diff --git a/tests/Unit/RedactingLogger.php b/tests/Unit/RedactingLogger.php new file mode 100644 index 0000000..c648479 --- /dev/null +++ b/tests/Unit/RedactingLogger.php @@ -0,0 +1,27 @@ +entries[] = ['level' => $level, 'message' => $message, 'context' => $context]; + } + + public function entries(): array + { + return $this->entries; + } +}