Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
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
49 changes: 48 additions & 1 deletion README.md
Original file line number Diff line number Diff line change
Expand Up @@ -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)

Expand All @@ -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`
Expand Down Expand Up @@ -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
<?php

declare(strict_types=1);

use TinyBlocks\Http\Logging\LogMiddleware;

# Bodies up to 4096 bytes are logged whole. A longer body is logged as an excerpt of at most 4096 bytes.
$middleware = LogMiddleware::create()
->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).
Expand Down
5 changes: 5 additions & 0 deletions phpstan.neon.dist
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -31,4 +35,5 @@ parameters:
paths:
- tests/Unit/CapturingLogger.php
- tests/Unit/LogMiddlewareTest.php
- tests/Unit/RedactingLogger.php
reportUnmatchedIgnoredErrors: true
11 changes: 11 additions & 0 deletions src/Exceptions/BodyLimitOutOfRange.php
Original file line number Diff line number Diff line change
@@ -0,0 +1,11 @@
<?php

declare(strict_types=1);

namespace TinyBlocks\Http\Logging\Exceptions;

use InvalidArgumentException;

final class BodyLimitOutOfRange extends InvalidArgumentException
{
}
127 changes: 127 additions & 0 deletions src/Internal/BodyLimit.php
Original file line number Diff line number Diff line change
@@ -0,0 +1,127 @@
<?php

declare(strict_types=1);

namespace TinyBlocks\Http\Logging\Internal;

use TinyBlocks\Http\Logging\Exceptions\BodyLimitOutOfRange;

final readonly class BodyLimit
{
private const string ELLIPSIS = '…';
private const int QUOTES_BYTES = 2;
private const int DEFAULT_BYTES = 2048;
private const int BRACKETS_BYTES = 2;
private const int ENCODING_FLAGS = (
JSON_UNESCAPED_UNICODE | JSON_UNESCAPED_SLASHES | JSON_INVALID_UTF8_SUBSTITUTE | JSON_THROW_ON_ERROR
);
private const int SEPARATOR_BYTES = 1;

private function __construct(private int $bytes)
{
}

private static function cut(string $text, int $available): string
{
$characters = [];
$budget = ($available - BodyLimit::sizeOf(value: self::ELLIPSIS));

foreach (mb_str_split(mb_strcut($text, 0, $budget)) as $character) {
$size = (BodyLimit::sizeOf(value: $character) - self::QUOTES_BYTES);

if ($size > $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;
}
}
10 changes: 7 additions & 3 deletions src/Internal/FailureOnlyLogExchange.php
Original file line number Diff line number Diff line change
Expand Up @@ -15,18 +15,21 @@
private function __construct(
private LoggerInterface $logger,
private LogRequest $request,
private BodyLimit $bodyLimit,
private Stopwatch $stopwatch
) {
}

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)
);
}
Expand All @@ -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()) {
Expand Down
10 changes: 7 additions & 3 deletions src/Internal/LogExchange.php
Original file line number Diff line number Diff line change
Expand Up @@ -15,21 +15,24 @@
private function __construct(
private LoggerInterface $logger,
private LogRequest $request,
private BodyLimit $bodyLimit,
private Stopwatch $stopwatch
) {
}

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)
);
}
Expand All @@ -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;
Expand Down
12 changes: 4 additions & 8 deletions src/Internal/LogRequest.php
Original file line number Diff line number Diff line change
Expand Up @@ -12,21 +12,21 @@
{
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();
$uri = $decodedRequest->uri();

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()
);
Expand All @@ -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];
}
}
18 changes: 9 additions & 9 deletions src/Internal/LogResponse.php
Original file line number Diff line number Diff line change
Expand Up @@ -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()
Expand Down Expand Up @@ -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];
}
}
Loading