Skip to content

Commit 7e01531

Browse files
turegjorupclaude
andcommitted
feat(logging): OTel semconv field names, redaction and exception processor
Build on the logging foundation (ADR 011): - Rename RequestContextProcessor fields to OpenTelemetry semantic conventions (http.request.method, http.route, url.path, client.address, enduser.id, screen.id, tenant.key); request_id/trace_id/span_id stay. - SensitiveDataProcessor (lowest priority, runs last) truncates client.address to a GDPR-safe form (IPv4 drops last octet, IPv6 keeps the /48) and redacts secret-bearing keys anywhere in context/extra. - ExceptionContextProcessor serialises a Throwable under the `exception` context key into a structured array with a depth-bounded previous chain, so no raw stack-trace string is emitted at info level. - Document the contract in docs/logging.md (channels, levels, message and context rules, field names, redaction guarantees). Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
1 parent 1243de6 commit 7e01531

15 files changed

Lines changed: 570 additions & 100 deletions

.env

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -120,8 +120,6 @@ SESSION_HANDLER_DSN=${REDIS_CACHE_DSN}
120120
HTTP_CLIENT_TIMEOUT=5
121121
# Maximum total duration in seconds for an HTTP request including transfer.
122122
HTTP_CLIENT_MAX_DURATION=30
123-
# Log level for outgoing HTTP requests (debug, info, notice, warning, error).
124-
HTTP_CLIENT_LOG_LEVEL=error
125123
###< Http Client ###
126124

127125
###> Logging ###
@@ -146,6 +144,8 @@ LOG_LEVEL_INTERACTIVE=
146144
# Threshold for Symfony's built-in cache channel (cache-adapter/Redis failures);
147145
# not an application channel. Empty or unset inherits LOG_LEVEL.
148146
LOG_LEVEL_CACHE=
147+
# Per-channel override (outbound HTTP client); empty or unset inherits LOG_LEVEL.
148+
LOG_LEVEL_OUTBOUND_HTTP=
149149
###< Logging ###
150150

151151
###> App ###

CHANGELOG.md

Lines changed: 8 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -21,6 +21,14 @@ All notable changes to this project will be documented in this file.
2121
- Renamed the outbound-HTTP-client log channel `app_http``outbound_http` and silenced
2222
Symfony's redundant native `http_client` channel logging (a `NullLogger` decorates it), so
2323
`LoggingHttpClient` is the single source of outbound-HTTP logs (no duplicate request logging).
24+
- Adopted OpenTelemetry semantic-convention field names for log records (including the HTTP
25+
client's `http.request.method` / `url.full` / `http.response.status_code` /
26+
`http.client.request.duration`), added GDPR-safe client-address truncation and secret-key
27+
redaction (`SensitiveDataProcessor`), and structured exception serialization under the
28+
`exception` context key (`ExceptionContextProcessor`). See `docs/logging.md`.
29+
The HTTP client now logs completed requests at `info` and failures at `error` on the
30+
`outbound_http` channel, thresholded by the new `LOG_LEVEL_OUTBOUND_HTTP` like every
31+
other channel; the `HTTP_CLIENT_LOG_LEVEL` env var is removed (use `LOG_LEVEL_OUTBOUND_HTTP`).
2432
- Removed the deprecated feed types `SparkleIOFeedType`, `EventDatabaseApiFeedType` and `KobaFeedType`.
2533
Made the unknown-feed-type handling consistent: **reads degrade, writes are rejected.** Feed sources
2634
(and feeds) that reference a removed type keep loading — item and collection reads return them with no

README.md

Lines changed: 11 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -578,6 +578,7 @@ LOG_LEVEL_MEDIA=
578578
LOG_LEVEL_FEED=
579579
LOG_LEVEL_INTERACTIVE=
580580
LOG_LEVEL_CACHE=
581+
LOG_LEVEL_OUTBOUND_HTTP=
581582
###< Logging ###
582583
```
583584

@@ -591,9 +592,16 @@ LOG_LEVEL_CACHE=
591592
`critical`). `info` reproduces the previous output.
592593

593594
**Default**: `info`.
594-
- LOG_LEVEL_AUTH, LOG_LEVEL_SCREEN, LOG_LEVEL_MEDIA, LOG_LEVEL_FEED, LOG_LEVEL_INTERACTIVE, LOG_LEVEL_CACHE:
595-
Per-channel threshold overrides. Empty or unset inherits `LOG_LEVEL`. Set one to raise or lower a single channel
596-
(e.g. `LOG_LEVEL_FEED=warning`) without affecting the others. An invalid level fails fast at boot.
595+
- LOG_LEVEL_AUTH, LOG_LEVEL_SCREEN, LOG_LEVEL_MEDIA, LOG_LEVEL_FEED, LOG_LEVEL_INTERACTIVE, LOG_LEVEL_CACHE,
596+
LOG_LEVEL_OUTBOUND_HTTP: Per-channel threshold overrides. Empty or unset inherits `LOG_LEVEL`. Set one to raise
597+
or lower a single channel (e.g. `LOG_LEVEL_FEED=warning`) without affecting the others. An invalid level fails
598+
fast at boot. (`LOG_LEVEL_CACHE` gates Symfony's built-in cache-adapter channel — Redis backend failures — not an
599+
application channel.)
600+
601+
The `outbound_http` channel carries outbound HTTP client logs (`LoggingHttpClient`): completed requests at
602+
`info`, failures at `error` — controlled by `LOG_LEVEL_OUTBOUND_HTTP` like every other channel. Symfony's
603+
built-in `http_client` channel (native, request-only logging) is silenced with a `NullLogger`, so
604+
`LoggingHttpClient` is the single source.
597605

598606
### Admin configuration
599607

UPGRADE.md

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -98,7 +98,7 @@ APP_REDIS_CACHE_DSN → REDIS_CACHE_DSN
9898
9999
APP_HTTP_CLIENT_TIMEOUT → HTTP_CLIENT_TIMEOUT
100100
APP_HTTP_CLIENT_MAX_DURATION → HTTP_CLIENT_MAX_DURATION
101-
APP_HTTP_CLIENT_LOG_LEVEL → HTTP_CLIENT_LOG_LEVEL
101+
APP_HTTP_CLIENT_LOG_LEVEL → LOG_LEVEL_OUTBOUND_HTTP
102102
103103
APP_INTERNAL_OIDC_METADATA_URL → INTERNAL_OIDC_METADATA_URL
104104
APP_INTERNAL_OIDC_CLIENT_ID → INTERNAL_OIDC_CLIENT_ID

config/packages/prod/monolog.yaml

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -14,7 +14,7 @@ monolog:
1414
outbound_http:
1515
type: stream
1616
path: '%env(resolve:LOG_PATH)%'
17-
level: info
17+
level: '%env(default:app.log_level:LOG_LEVEL_OUTBOUND_HTTP)%'
1818
channels: ['outbound_http']
1919
formatter: monolog.formatter.json
2020
# One always-on handler per domain channel. A Monolog handler carries a

config/services.yaml

Lines changed: 8 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -56,7 +56,6 @@ services:
5656
arguments:
5757
$client: '@.inner'
5858
$logger: '@monolog.logger.outbound_http'
59-
$logLevel: '%env(string:HTTP_CLIENT_LOG_LEVEL)%'
6059

6160
# Silence Symfony's native http_client logging at the source: it is
6261
# request-only and redundant with LoggingHttpClient (outbound_http channel),
@@ -75,6 +74,14 @@ services:
7574
App\Logger\Processor\TraceContextProcessor:
7675
tags: [{ name: monolog.processor }]
7776

77+
App\Logger\Processor\ExceptionContextProcessor:
78+
tags: [{ name: monolog.processor, priority: -90 }]
79+
80+
# Lowest priority: runs last so it scrubs everything the other processors
81+
# added (e.g. the raw client.address set by RequestContextProcessor).
82+
App\Logger\Processor\SensitiveDataProcessor:
83+
tags: [{ name: monolog.processor, priority: -100 }]
84+
7885
# Logs security outcomes on the `auth` channel (logging only).
7986
App\Logger\EventSubscriber\AuthLoggingSubscriber:
8087
arguments:

docs/logging.md

Lines changed: 133 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,133 @@
1+
# Logging
2+
3+
This service emits **structured JSON logs** to `php://stderr`. Every record is enriched
4+
with request, identity and trace context, and serialised so it can be ingested by a log
5+
aggregator later without changes here. The decisions behind this are recorded in
6+
[ADR 011](adr/011-structured-logging.md).
7+
8+
The conventions below are **enforced in CI** by project-local PHPStan rules
9+
(`logging.silentCatch`, `logging.interpolatedLogMessage`, `logging.exceptionContextKey`).
10+
A build fails if you break them.
11+
12+
## Channels
13+
14+
Inject a channel-specific logger instead of the generic one, so records can be routed and
15+
filtered per domain. Bind the channel in `config/services.yaml`:
16+
17+
```yaml
18+
App\Service\FeedService:
19+
arguments:
20+
$logger: '@monolog.logger.feed'
21+
```
22+
23+
| Channel | Use for |
24+
|---|---|
25+
| `outbound_http` | Outbound HTTP client calls (`LoggingHttpClient`). Named to stay clear of Symfony's built-in `http_client` channel, whose native (request-only) logging is silenced with a `NullLogger`. |
26+
| `auth` | Authentication and authorization outcomes (login, logout, JWT/OIDC). |
27+
| `screen` | Screen-client binding, screen authentication, screen status. |
28+
| `media` | Media upload, thumbnailing, storage. |
29+
| `feed` | Feed fetching/parsing (`FeedService`, feed types). |
30+
| `interactive` | Interactive slides (booking, instant book). |
31+
| `cache` | **Not an application channel** — Symfony's built-in cache-adapter channel. Given a dedicated handler so cache-adapter (Redis) backend failures surface instead of being dropped by the `fingers_crossed` gate. No application code writes to it. |
32+
| `database` | Database connection failures (see below). |
33+
34+
## Level guidance
35+
36+
| Level | When |
37+
|---|---|
38+
| `debug` | Developer detail; verbose, off in production action buffering. |
39+
| `info` | Normal, noteworthy events (auth success, batch completed). |
40+
| `notice` | Normal but significant (config fallback applied). |
41+
| `warning` | Something recoverable went wrong (auth failure, flapping feed, malformed payload). |
42+
| `error` | An operation failed and a user/screen is affected. |
43+
| `critical` | A subsystem is down (database connection pressure/unreachable). |
44+
45+
## Message and context rules
46+
47+
1. **The message is a static string.** Never interpolate variables into it.
48+
49+
```php
50+
// ❌ flagged by logging.interpolatedLogMessage
51+
$logger->warning("Feed {$source->getId()} failed");
52+
53+
// ✅ static message, data in context
54+
$logger->warning('Feed fetch failed', ['feed_source_id' => (string) $source->getId()]);
55+
```
56+
57+
PSR-3 `{placeholder}` braces resolved from the context array are fine.
58+
59+
2. **Exceptions go under the `exception` context key — never any other key, never
60+
interpolated.**
61+
62+
```php
63+
// ❌ flagged by logging.exceptionContextKey
64+
$logger->error('Booking failed', ['error' => $e]);
65+
66+
// ✅
67+
$logger->error('Booking failed', ['exception' => $e]);
68+
```
69+
70+
`ExceptionContextProcessor` turns the `\Throwable` into a structured array
71+
(`class`, `message`, `code`, `file`, `line`, bounded `previous` chain). No raw
72+
multi-line stack-trace string is emitted at info level.
73+
74+
3. **Never swallow an exception silently.** A `catch` must log it (under `exception`),
75+
rethrow it (optionally wrapped), or be explicitly annotated when the silence is
76+
intentional:
77+
78+
```php
79+
try {
80+
$optional = $this->parse($payload);
81+
} catch (\JsonException $e) {
82+
// @phpstan-ignore logging.silentCatch (optional metadata; absence is expected)
83+
}
84+
```
85+
86+
This is enforced by `logging.silentCatch`.
87+
88+
## Field names (OpenTelemetry semantic conventions)
89+
90+
Field names follow [OpenTelemetry semantic conventions](https://opentelemetry.io/docs/specs/semconv/)
91+
as strictly as the framework allows, so the logs stay forward-compatible with an OTel
92+
collector should one be introduced:
93+
94+
| Field | Meaning |
95+
|---|---|
96+
| `request_id` | Per-request id (inbound `X-Request-Id` or minted). |
97+
| `http.request.method` | HTTP method. |
98+
| `http.route` | Matched route's **path template**, e.g. `/v2/screens/{id}` — id-free and low-cardinality, with the API Platform `.{_format}` suffix stripped. **Set only when a route matched** (per OTel guidance), and **never** the concrete id-bearing URL. |
99+
| `url.path` | The concrete request path, **including** ids (e.g. `/v2/screens/01HXYZ…`). This is the field that carries the real path; `http.route` is its templated, id-free counterpart. |
100+
| `client.address` | **Truncated** client address (see redaction). |
101+
| `enduser.id` | Back-office user identifier. |
102+
| `screen.id` | Screen id (for screen-token requests). |
103+
| `tenant.key` | Active tenant key. |
104+
| `trace_id` / `span_id` | W3C trace context, when a `traceparent` header is present. |
105+
106+
Strict OTel notes: `http.route` is the **path template** the server matched, not the
107+
Symfony route *name* and not the concrete path; it is omitted entirely (rather than set to
108+
an empty/placeholder value) when no route matched. `enduser.id` and `screen.id` are mutually
109+
exclusive. Fields that don't apply to a record are absent, never `null`.
110+
111+
### `extra` (ambient request) vs `context` (the event)
112+
113+
The processors above add the **inbound** request's attributes to every record's `extra`
114+
(`http.request.method`, `http.route`, `url.path`, `client.address`, …). A log *call* may
115+
put its own subject's attributes in `context` using the same OTel names — for example the
116+
outbound HTTP client (`outbound_http` channel) logs `http.request.method` / `url.full` /
117+
`http.response.status_code` for the call it just made. So a record for an outbound call can
118+
carry `extra.http.request.method` (the inbound API request) **and** `context.http.request.method`
119+
(the outbound call). This is intentional and mirrors OTel's server-span vs client-span split:
120+
`extra` is the ambient request the worker is serving; `context` is the event being logged.
121+
The two stay in separate bags, so there is no key collision.
122+
123+
## Redaction guarantees
124+
125+
`SensitiveDataProcessor` runs last and is a backstop, not a license to log secrets:
126+
127+
- `client.address` is **truncated** — IPv4 drops the last octet (`203.0.113.5` →
128+
`203.0.113.0`); IPv6 keeps the `/48` and zeroes the rest. No full client IP is emitted.
129+
- Any key whose name contains `password`, `passwd`, `secret`, `authorization`, `api_key`,
130+
`apikey`, `token`, `credential` or `bearer` is replaced with `[redacted]`, at any depth
131+
in `context`/`extra`.
132+
133+
Still: do not put credentials or token strings into log context in the first place.

src/HttpClient/LoggingHttpClient.php

Lines changed: 25 additions & 15 deletions
Original file line numberDiff line numberDiff line change
@@ -14,7 +14,6 @@ class LoggingHttpClient implements HttpClientInterface
1414
public function __construct(
1515
private HttpClientInterface $client,
1616
private readonly LoggerInterface $logger,
17-
private readonly string $logLevel = 'error',
1817
) {}
1918

2019
public function request(string $method, string $url, array $options = []): ResponseInterface
@@ -26,30 +25,41 @@ public function request(string $method, string $url, array $options = []): Respo
2625
try {
2726
$statusCode = $response->getStatusCode();
2827
} catch (\Throwable $throwable) {
29-
$duration = round((microtime(true) - $startTime) * 1000);
30-
31-
$this->logger->error('{method} {url} failed after {duration}ms: {error}', [
32-
'method' => $method,
33-
'url' => $url,
34-
'duration' => $duration,
35-
'error' => $throwable->getMessage(),
28+
// OTel semantic conventions for an HTTP client call; the exception
29+
// goes under the `exception` key so ExceptionContextProcessor
30+
// serialises it (see docs/logging.md).
31+
$this->logger->error('{http.request.method} {url.full} failed', [
32+
'http.request.method' => $method,
33+
'url.full' => $url,
34+
'http.client.request.duration' => $this->durationSeconds($startTime),
35+
'exception' => $throwable,
3636
]);
3737

3838
throw $throwable;
3939
}
4040

41-
$duration = round((microtime(true) - $startTime) * 1000);
42-
43-
$this->logger->log($this->logLevel, '{method} {url} {status_code} {duration}ms', [
44-
'method' => $method,
45-
'url' => $url,
46-
'status_code' => $statusCode,
47-
'duration' => $duration,
41+
// Natural severity: a completed request is info; failures log at error
42+
// (above). Visibility is controlled by the outbound_http handler
43+
// threshold (LOG_LEVEL_OUTBOUND_HTTP), consistent with every channel.
44+
$this->logger->info('{http.request.method} {url.full} {http.response.status_code} ({http.client.request.duration}s)', [
45+
'http.request.method' => $method,
46+
'url.full' => $url,
47+
'http.response.status_code' => $statusCode,
48+
'http.client.request.duration' => $this->durationSeconds($startTime),
4849
]);
4950

5051
return $response;
5152
}
5253

54+
/**
55+
* Elapsed time since $startTime in seconds (OTel
56+
* `http.client.request.duration` unit), rounded to 0.1 ms.
57+
*/
58+
private function durationSeconds(float $startTime): float
59+
{
60+
return round(microtime(true) - $startTime, 4);
61+
}
62+
5363
public function stream(ResponseInterface|iterable $responses, ?float $timeout = null): ResponseStreamInterface
5464
{
5565
return $this->client->stream($responses, $timeout);
Lines changed: 50 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,50 @@
1+
<?php
2+
3+
declare(strict_types=1);
4+
5+
namespace App\Logger\Processor;
6+
7+
use Monolog\LogRecord;
8+
use Monolog\Processor\ProcessorInterface;
9+
10+
/**
11+
* Replaces a `\Throwable` under the `exception` context key with a structured
12+
* array (class, message, code, file, line and a bounded `previous` chain) so a
13+
* raw multi-line stack-trace string is never emitted at info level in
14+
* production. Non-exception context is left untouched.
15+
*/
16+
final class ExceptionContextProcessor implements ProcessorInterface
17+
{
18+
private const MAX_DEPTH = 5;
19+
20+
public function __invoke(LogRecord $record): LogRecord
21+
{
22+
$context = $record->context;
23+
if (isset($context['exception']) && $context['exception'] instanceof \Throwable) {
24+
$context['exception'] = $this->normalize($context['exception'], self::MAX_DEPTH);
25+
26+
return $record->with(context: $context);
27+
}
28+
29+
return $record;
30+
}
31+
32+
/** @return array<string, mixed> */
33+
private function normalize(\Throwable $e, int $depth): array
34+
{
35+
$data = [
36+
'class' => $e::class,
37+
'message' => $e->getMessage(),
38+
'code' => $e->getCode(),
39+
'file' => $e->getFile(),
40+
'line' => $e->getLine(),
41+
];
42+
43+
$previous = $e->getPrevious();
44+
if (null !== $previous && $depth > 1) {
45+
$data['previous'] = $this->normalize($previous, $depth - 1);
46+
}
47+
48+
return $data;
49+
}
50+
}

0 commit comments

Comments
 (0)