Merge pull request #479 from os2display/feature/structured-logging-semconv

Author: turegjorup

.env

@@ -120,8 +120,6 @@ SESSION_HANDLER_DSN=${REDIS_CACHE_DSN}
 HTTP_CLIENT_TIMEOUT=5
 # Maximum total duration in seconds for an HTTP request including transfer.
 HTTP_CLIENT_MAX_DURATION=30
-# Log level for outgoing HTTP requests (debug, info, notice, warning, error).
-HTTP_CLIENT_LOG_LEVEL=error
 ###< Http Client ###
 
 ###> Logging ###
@@ -146,6 +144,8 @@ LOG_LEVEL_INTERACTIVE=
 # Threshold for Symfony's built-in cache channel (cache-adapter/Redis failures);
 # not an application channel. Empty or unset inherits LOG_LEVEL.
 LOG_LEVEL_CACHE=
+# Per-channel override (outbound HTTP client); empty or unset inherits LOG_LEVEL.
+LOG_LEVEL_OUTBOUND_HTTP=
 ###< Logging ###
 
 ###> App ###

CHANGELOG.md

@@ -14,6 +14,16 @@ All notable changes to this project will be documented in this file.
 - Renamed the outbound-HTTP-client log channel `app_http` → `outbound_http` and silenced
   Symfony's redundant native `http_client` channel logging (a `NullLogger` decorates it), so
   `LoggingHttpClient` is the single source of outbound-HTTP logs (no duplicate request logging).
+- Adopted OpenTelemetry semantic-convention field names for log records: request/identity
+  context (`http.route`, `url.path`, `client.address`, `user.id` XOR `screen.id`,
+  `tenant.key`) plus the HTTP client's `http.request.method` / `url.full` /
+  `http.response.status_code` / `http.client.request.duration`. Added GDPR-safe
+  client-address truncation and secret-key redaction (`SensitiveDataProcessor`), and
+  structured exception serialization (`type`, `message`, …) under the `exception` context
+  key (`ExceptionContextProcessor`). See `docs/logging.md`.
+  The HTTP client now logs completed requests at `info` and failures at `error` on the
+  `outbound_http` channel, thresholded by the new `LOG_LEVEL_OUTBOUND_HTTP` like every
+  other channel; the `HTTP_CLIENT_LOG_LEVEL` env var is removed (use `LOG_LEVEL_OUTBOUND_HTTP`).
 
 ## [3.0.0-rc4] - 2026-06-04
 

README.md

@@ -578,6 +578,7 @@ LOG_LEVEL_MEDIA=
 LOG_LEVEL_FEED=
 LOG_LEVEL_INTERACTIVE=
 LOG_LEVEL_CACHE=
+LOG_LEVEL_OUTBOUND_HTTP=
 ###< Logging ###
 ```
 
@@ -591,9 +592,16 @@ LOG_LEVEL_CACHE=
   `critical`). `info` reproduces the previous output.
 
   **Default**: `info`.
-- LOG_LEVEL_AUTH, LOG_LEVEL_SCREEN, LOG_LEVEL_MEDIA, LOG_LEVEL_FEED, LOG_LEVEL_INTERACTIVE, LOG_LEVEL_CACHE:
-  Per-channel threshold overrides. Empty or unset inherits `LOG_LEVEL`. Set one to raise or lower a single channel
-  (e.g. `LOG_LEVEL_FEED=warning`) without affecting the others. An invalid level fails fast at boot.
+- LOG_LEVEL_AUTH, LOG_LEVEL_SCREEN, LOG_LEVEL_MEDIA, LOG_LEVEL_FEED, LOG_LEVEL_INTERACTIVE, LOG_LEVEL_CACHE,
+  LOG_LEVEL_OUTBOUND_HTTP: Per-channel threshold overrides. Empty or unset inherits `LOG_LEVEL`. Set one to raise
+  or lower a single channel (e.g. `LOG_LEVEL_FEED=warning`) without affecting the others. An invalid level fails
+  fast at boot. (`LOG_LEVEL_CACHE` gates Symfony's built-in cache-adapter channel — Redis backend failures — not an
+  application channel.)
+
+The `outbound_http` channel carries outbound HTTP client logs (`LoggingHttpClient`): completed requests at
+`info`, failures at `error` — controlled by `LOG_LEVEL_OUTBOUND_HTTP` like every other channel. Symfony's
+built-in `http_client` channel (native, request-only logging) is silenced with a `NullLogger`, so
+`LoggingHttpClient` is the single source.
 
 ### Admin configuration
 

UPGRADE.md

@@ -98,7 +98,7 @@ APP_REDIS_CACHE_DSN                              → REDIS_CACHE_DSN
 
 APP_HTTP_CLIENT_TIMEOUT                          → HTTP_CLIENT_TIMEOUT
 APP_HTTP_CLIENT_MAX_DURATION                     → HTTP_CLIENT_MAX_DURATION
-APP_HTTP_CLIENT_LOG_LEVEL                        → HTTP_CLIENT_LOG_LEVEL
+APP_HTTP_CLIENT_LOG_LEVEL                        → LOG_LEVEL_OUTBOUND_HTTP
 
 APP_INTERNAL_OIDC_METADATA_URL                   → INTERNAL_OIDC_METADATA_URL
 APP_INTERNAL_OIDC_CLIENT_ID                      → INTERNAL_OIDC_CLIENT_ID

config/packages/prod/monolog.yaml

@@ -4,6 +4,22 @@ monolog:
             type: fingers_crossed
             action_level: error
             handler: nested
+            # Exclude every channel that has its own always-on handler below: the
+            # fingers_crossed gate has no channels filter by default, so on an error
+            # it would flush buffered per-channel records to `nested` in addition to
+            # the dedicated handler that already wrote them — emitting each twice.
+            # `main` therefore handles only the default `app` channel (and any
+            # channel without a dedicated handler).
+            channels:
+                [
+                    '!outbound_http',
+                    '!auth',
+                    '!screen',
+                    '!media',
+                    '!feed',
+                    '!interactive',
+                    '!cache',
+                ]
             excluded_http_codes: [404, 405]
             buffer_size: 50 # How many messages should be saved? Prevent memory leaks
         nested:
@@ -14,7 +30,7 @@ monolog:
         outbound_http:
             type: stream
             path: '%env(resolve:LOG_PATH)%'
-            level: info
+            level: '%env(default:app.log_level:LOG_LEVEL_OUTBOUND_HTTP)%'
             channels: ['outbound_http']
             formatter: monolog.formatter.json
         # One always-on handler per domain channel. A Monolog handler carries a

config/services.yaml

@@ -60,8 +60,7 @@ services:
         decorates: http_client
         arguments:
             $client: '@.inner'
-            $logger: '@monolog.logger.outbound_http'
-            $logLevel: '%env(string:HTTP_CLIENT_LOG_LEVEL)%'
+            $outboundHttpLogger: '@monolog.logger.outbound_http'
 
     # Silence Symfony's native http_client logging at the source: it is
     # request-only and redundant with LoggingHttpClient (outbound_http channel),
@@ -80,6 +79,14 @@ services:
     App\Logger\Processor\TraceContextProcessor:
         tags: [{ name: monolog.processor }]
 
+    App\Logger\Processor\ExceptionContextProcessor:
+        tags: [{ name: monolog.processor, priority: -90 }]
+
+    # Lowest priority: runs last so it scrubs everything the other processors
+    # added (e.g. the raw client.address set by RequestContextProcessor).
+    App\Logger\Processor\SensitiveDataProcessor:
+        tags: [{ name: monolog.processor, priority: -100 }]
+
     # Logs security outcomes on the `auth` channel (logging only).
     #
     # Channel loggers are bound explicitly rather than via MonologBundle's channel

docs/logging.md

@@ -0,0 +1,147 @@
+# Logging
+
+This service emits **structured JSON logs** to `php://stderr`. Every record is enriched
+with request, identity and trace context, and serialised so it can be ingested by a log
+aggregator later without changes here. The decisions behind this are recorded in
+[ADR 011](adr/011-structured-logging.md).
+
+The conventions below are **enforced in CI** by project-local PHPStan rules
+(`logging.silentCatch`, `logging.interpolatedLogMessage`, `logging.exceptionContextKey`).
+A build fails if you break them.
+
+## Channels
+
+Inject a channel-specific logger instead of the generic one, so records can be routed and
+filtered per domain. Name the constructor parameter for its channel and bind it explicitly
+in `config/services.yaml`:
+
+```yaml
+App\Service\FeedService:
+    arguments:
+        $feedLogger: '@monolog.logger.feed'
+```
+
+| Channel | Use for |
+|---|---|
+| `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`. |
+| `auth` | Authentication and authorization outcomes (login, logout, JWT/OIDC). |
+| `screen` | Screen-client binding, screen authentication, screen status. |
+| `media` | Media upload, thumbnailing, storage. |
+| `feed` | Feed fetching/parsing (`FeedService`, feed types). |
+| `interactive` | Interactive slides (booking, instant book). |
+| `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. |
+| `database` | Database connection failures (see below). |
+
+## Level guidance
+
+| Level | When |
+|---|---|
+| `debug` | Developer detail; verbose, off in production action buffering. |
+| `info` | Normal, noteworthy events (auth success, batch completed). |
+| `notice` | Normal but significant (config fallback applied). |
+| `warning` | Something recoverable went wrong (auth failure, flapping feed, malformed payload). |
+| `error` | An operation failed and a user/screen is affected. |
+| `critical` | A subsystem is down (database connection pressure/unreachable). |
+
+## Message and context rules
+
+1. **The message is a static string.** Never interpolate variables into it.
+
+   ```php
+   // ❌ flagged by logging.interpolatedLogMessage
+   $logger->warning("Feed {$source->getId()} failed");
+
+   // ✅ static message, data in context
+   $logger->warning('Feed fetch failed', ['feed_source_id' => (string) $source->getId()]);
+   ```
+
+   PSR-3 `{placeholder}` braces resolved from the context array are fine.
+
+2. **Exceptions go under the `exception` context key — never any other key, never
+   interpolated.**
+
+   ```php
+   // ❌ flagged by logging.exceptionContextKey
+   $logger->error('Booking failed', ['error' => $e]);
+
+   // ✅
+   $logger->error('Booking failed', ['exception' => $e]);
+   ```
+
+   `ExceptionContextProcessor` turns the `\Throwable` into a structured array
+   (`type`, `message`, `code`, `file`, `line`, bounded `previous` chain). No raw
+   multi-line stack-trace string is emitted at info level.
+
+3. **Never swallow an exception silently.** A `catch` must log it (under `exception`),
+   rethrow it (optionally wrapped), or be explicitly annotated when the silence is
+   intentional:
+
+   ```php
+   try {
+       $optional = $this->parse($payload);
+   } catch (\JsonException $e) {
+       // @phpstan-ignore logging.silentCatch (optional metadata; absence is expected)
+   }
+   ```
+
+   This is enforced by `logging.silentCatch`.
+
+## Field names (OpenTelemetry semantic conventions)
+
+Field names follow [OpenTelemetry semantic conventions](https://opentelemetry.io/docs/specs/semconv/)
+as strictly as the framework allows, so the logs stay forward-compatible with an OTel
+collector should one be introduced:
+
+| Field | Meaning |
+|---|---|
+| `request_id` | Per-request id (inbound `X-Request-Id` or minted). |
+| `http.request.method` | HTTP method. |
+| `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. |
+| `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. |
+| `client.address` | Client address — **truncated** for users/anonymous callers, kept **in full** for screen clients (see redaction). |
+| `user.id` | Back-office user identifier. |
+| `screen.id` | Screen id (for screen-token requests). |
+| `tenant.key` | Active tenant key. |
+| `trace_id` / `span_id` | W3C trace context, when a `traceparent` header is present. |
+
+Strict OTel notes: `http.route` is the **path template** the server matched, not the
+Symfony route *name* and not the concrete path; it is omitted entirely (rather than set to
+an empty/placeholder value) when no route matched. `user.id` and `screen.id` are mutually
+exclusive. Fields that don't apply to a record are absent, never `null`.
+
+### `extra` (ambient request) vs `context` (the event)
+
+The processors above add the **inbound** request's attributes to every record's `extra`
+(`http.request.method`, `http.route`, `url.path`, `client.address`, …). A log *call* may
+put its own subject's attributes in `context` using the same OTel names — for example the
+outbound HTTP client (`outbound_http` channel) logs `http.request.method` / `url.full` /
+`http.response.status_code` / `http.client.request.duration` for the call it just made.
+So a record for an outbound call can carry `extra.http.request.method` (the inbound API
+request) **and** `context.http.request.method`
+(the outbound call). This is intentional and mirrors OTel's server-span vs client-span split:
+`extra` is the ambient request the worker is serving; `context` is the event being logged.
+The two stay in separate bags, so there is no key collision.
+
+## Redaction guarantees
+
+`SensitiveDataProcessor` runs last and is a backstop, not a license to log secrets:
+
+- `client.address` is **truncated** for back-office users and anonymous callers — IPv4
+  drops the last octet (`203.0.113.5` → `203.0.113.0`); IPv6 keeps the `/48` and zeroes the
+  rest; an address that does not parse as an IP is replaced with `[redacted]`.
+  **Screen-client (kiosk) requests are exempt and keep their full IP.** A kiosk is an
+  unattended public display, not a personal device, so it falls outside GDPR, and the full
+  address helps identify a specific screen. A record is treated as a screen client when it
+  carries `screen.id` (set upstream by `RequestContextProcessor`).
+- Any key whose name contains `password`, `passwd`, `secret`, `authorization`, `api_key`,
+  `apikey`, `token`, `credential` or `bearer` is replaced with `[redacted]`, at any depth
+  in `context`/`extra`.
+
+`SensitiveDataProcessor` matches on the context **key name only** — it never inspects
+*values*. A secret carried inside a value under an innocuous key (most commonly a URL with
+`?api_key=…` in its query string) is therefore **not** caught by the backstop and must be
+sanitised at the source. The outbound HTTP client does this: `LoggingHttpClient` redacts the
+query string of `url.full` wholesale (`https://host/path?[redacted]`) and drops any userinfo
+(`user:pass@`) before logging, so credentials in an outbound URL never reach the log.
+
+Still: do not put credentials or token strings into log context in the first place.

src/HttpClient/LoggingHttpClient.php

@@ -11,10 +11,11 @@
 
 class LoggingHttpClient implements HttpClientInterface
 {
+    private const REDACTED = '[redacted]';
+
     public function __construct(
         private HttpClientInterface $client,
-        private readonly LoggerInterface $logger,
-        private readonly string $logLevel = 'error',
+        private readonly LoggerInterface $outboundHttpLogger,
     ) {}
 
     public function request(string $method, string $url, array $options = []): ResponseInterface
@@ -23,33 +24,88 @@ public function request(string $method, string $url, array $options = []): Respo
 
         $response = $this->client->request($method, $url, $options);
 
+        // The actual request uses the full $url; only the logged value is
+        // sanitised (see sanitizeUrl).
+        $loggedUrl = $this->sanitizeUrl($url);
+
         try {
             $statusCode = $response->getStatusCode();
         } catch (\Throwable $throwable) {
-            $duration = round((microtime(true) - $startTime) * 1000);
-
-            $this->logger->error('{method} {url} failed after {duration}ms: {error}', [
-                'method' => $method,
-                'url' => $url,
-                'duration' => $duration,
-                'error' => $throwable->getMessage(),
+            // OTel semantic conventions for an HTTP client call; the exception
+            // goes under the `exception` key so ExceptionContextProcessor
+            // serialises it (see docs/logging.md).
+            $this->outboundHttpLogger->error('{http.request.method} {url.full} failed', [
+                'http.request.method' => $method,
+                'url.full' => $loggedUrl,
+                'http.client.request.duration' => $this->durationSeconds($startTime),
+                'exception' => $throwable,
             ]);
 
             throw $throwable;
         }
 
-        $duration = round((microtime(true) - $startTime) * 1000);
-
-        $this->logger->log($this->logLevel, '{method} {url} {status_code} {duration}ms', [
-            'method' => $method,
-            'url' => $url,
-            'status_code' => $statusCode,
-            'duration' => $duration,
+        // Natural severity: a completed request is info; failures log at error
+        // (above). Visibility is controlled by the outbound_http handler
+        // threshold (LOG_LEVEL_OUTBOUND_HTTP), consistent with every channel.
+        $this->outboundHttpLogger->info('{http.request.method} {url.full} {http.response.status_code} ({http.client.request.duration}s)', [
+            'http.request.method' => $method,
+            'url.full' => $loggedUrl,
+            'http.response.status_code' => $statusCode,
+            'http.client.request.duration' => $this->durationSeconds($startTime),
         ]);
 
         return $response;
     }
 
+    /**
+     * Sanitises a URL for logging: the query string is replaced wholesale with
+     * a redaction marker (`?[redacted]`), and the fragment and any userinfo
+     * (`user:pass@`) are dropped, keeping scheme + host + port + path.
+     *
+     * The {@see \App\Logger\Processor\SensitiveDataProcessor} backstop only
+     * redacts by context *key* name; a credential carried in a URL *value*
+     * (`?api_key=…`, `?token=…`, or `https://user:pass@host/…`) would otherwise
+     * pass through unredacted. URL values must therefore be sanitised here, at
+     * the source. The query is where secrets live, so its contents are redacted
+     * rather than dropped — the `?[redacted]` marker preserves the signal that
+     * a query was present without leaking any of its values.
+     */
+    private function sanitizeUrl(string $url): string
+    {
+        $parts = parse_url($url);
+        if (false === $parts) {
+            // Unparseable: redact from the first query delimiter onward rather
+            // than risk emitting a credential-bearing tail.
+            $base = explode('#', explode('?', $url, 2)[0], 2)[0];
+
+            return str_contains($url, '?') ? $base.'?'.self::REDACTED : $base;
+        }
+
+        $scheme = isset($parts['scheme']) ? $parts['scheme'].'://' : '';
+        $host = $parts['host'] ?? '';
+        $port = isset($parts['port']) ? ':'.$parts['port'] : '';
+        $path = $parts['path'] ?? '';
+        // Show that a query existed, but never its contents.
+        $query = isset($parts['query']) ? '?'.self::REDACTED : '';
+
+        // No host (e.g. a relative URL resolved against the client's base_uri):
+        // keep just the path, still with the query redacted.
+        if ('' === $host) {
+            return $path.$query;
+        }
+
+        return $scheme.$host.$port.$path.$query;
+    }
+
+    /**
+     * Elapsed time since $startTime in seconds (OTel
+     * `http.client.request.duration` unit), rounded to 0.1 ms.
+     */
+    private function durationSeconds(float $startTime): float
+    {
+        return round(microtime(true) - $startTime, 4);
+    }
+
     public function stream(ResponseInterface|iterable $responses, ?float $timeout = null): ResponseStreamInterface
     {
         return $this->client->stream($responses, $timeout);