feat: add optional structured JSON logging

.github/workflows/model-smoke.yml

@@ -18,8 +18,9 @@ on:
       - worker/ai_bridge/jobs.py
       # The worker's HTTP handling, which every model test and the MCP workers' health check go through.
       - worker/ai_bridge/server.py
-      # Imported by both: the counters every model job passes through.
+      # Imported by both: the counters and the log lines every model job passes through.
       - worker/ai_bridge/metrics.py
+      - worker/ai_bridge/log.py
       - scripts/benchmark.py
       - scripts/ner_measure.py
       - scripts/public_data.py

CHANGELOG.md

@@ -10,6 +10,7 @@ All notable changes to this project are documented in this file. The format foll
 
 - A graceful drain: on SIGTERM or SIGINT the worker answers `POST /v1/jobs` with 503 `draining` and `Retry-After: 1`, fails queued jobs as `service_restarted` at once, keeps answering `GET`, and lets running jobs finish for up to `BRIDGE_DRAIN_SECONDS` (integer 0 to 300, default 30) before it stops; a second signal stops it at once.
 - `GET /readyz`, behind any configured token like `/healthz`: 200 when the worker is not draining and a child is idle with its backend's models loaded, otherwise 503 with a reason (`draining`, `no_idle_child`, `models_loading`). A child now loads its backend's models as it starts instead of on its first job. Compose's MCP workers report healthy only once ready.
+- Optional structured logging: `BRIDGE_LOG=json` writes one JSON object per line on stderr, best effort (a full queue or the exit can drop lines), a `request` line after each reply (method, route template, status, duration, the token's name), a `job` line when a job ends (job ID, task, owner, terminal status, queue and run times), and `start`, `drain` and `stop` lines. A fixed schema checked value by value keeps inputs, results, headers, query strings, tokens and exception text out; a stderr that blocks or fails never holds a request. `off`, the default, writes nothing, and any other value stops the worker at start naming `BRIDGE_LOG`.
 - A full connection budget (32) is answered 503 `service_busy` with `Retry-After: 1` and `Connection: close` instead of a closed socket, and a request line over 8 KiB or a header block over 16 KiB is refused with 431 `headers_too_large`.
 
 ### Changed

README.md

@@ -13,6 +13,7 @@ Includes a FrankenPHP worker-mode example, deterministic fault tests, and an opt
 - Bounded concurrency, queue/result capacity, retention, request sizes and execution deadlines.
 - Cancellation, progress polling, crash detection and generic errors that omit internal exception text.
 - `GET /metrics` on the worker: aggregate job counts, queue depth, pool readiness and duration histograms in the Prometheus text format, behind the service token and carrying no job content; counters reset on restart ([the protocol](docs/protocol.md#metrics)).
+- Optional structured logging with `BRIDGE_LOG=json`: best effort, one JSON line on stderr per request and per finished job, plus start, drain and stop, with a fixed schema that never holds inputs, results, headers, query strings, tokens or exception text; off by default ([the protocol](docs/protocol.md#logging)).
 - A FrankenPHP example that submits work and returns a job ID immediately.
 - A stdio MCP server with one tool per task, a second client of the same protocol beside the PHP client, plus an index builder over the protocol and a `bridge_search` tool that searches what it built, returning offsets and snippets rather than vectors, a compose service that puts the pinned ONNX models behind it, and a ten-question evaluation for LLM hosts with a runner for the Claude Code CLI; see [the MCP guide](docs/mcp.md).
 - CPU inference with `cross-encoder/ms-marco-TinyBERT-L2-v2`, `sentence-transformers/all-MiniLM-L6-v2` and int8 `dslim/bert-base-NER` and `dslim/bert-base-NER-uncased` through ONNX Runtime, using pinned model files and wheel hashes.

docs/protocol.md

@@ -81,3 +81,17 @@ On SIGTERM or SIGINT the worker drains: every `POST /v1/jobs` is answered 503 `d
 | `bridge_info` | gauge | `protocol="1"`, `backend` | Always 1 |
 
 Both histograms have the buckets 0.05, 0.1, 0.25, 0.5, 1, 2.5, 5, 10, 30, 60 and 300 seconds and `+Inf`, cumulative as the format requires, with `_sum` and `_count`. A scrape copies the numbers under the store's lock and formats them without it, so it never waits for a job. An invalid submission (400) creates no job and counts nothing.
+
+## Logging
+
+The worker writes no log by default: `BRIDGE_LOG` unset, empty or `off` writes nothing at all. With `BRIDGE_LOG=json` it writes one JSON object per line on stderr; any other value stops the worker at start with a message naming the variable. Every line has `ts` (UTC, ISO 8601 with milliseconds and `Z`), `level` (`info` or `warning`) and `event`, then exactly the keys of its event, `null` where a value is unknown or does not apply. Values come only from fixed sets, numbers, a job ID or a token's name: no input, result, header, query string, path, idempotency key, token, error message or exception text is ever written, and a key outside the table is dropped by the formatter whatever a caller passes. Lines are written by a thread of their own behind a queue of 1024: a stderr that blocks or fails never holds or fails a request or a job, and lines that do not fit are dropped. Logging is best effort: lines may be dropped when the queue is full or at exit. A stop waits about 2 s at most for the queued lines to be written, and a process that ends without that stop (killed, for instance) loses what was still queued.
+
+| `event` | When | Keys |
+| --- | --- | --- |
+| `request` | After the reply to a request is sent, a 401, 408, 413, 431 and 503 included; a connection that ends before any reply writes none | `method` (`GET`, `POST`, `other`, or `null` when the request line could not be read or parsed), `route` (`/healthz`, `/readyz`, `/metrics`, `/v1/jobs`, `/v1/jobs/{id}`, `/v1/jobs/{id}/cancel`, or `other` for any other path, a query string included), `status`, `duration_ms` (from the start of reading the request to the reply sent), `owner` (the token's name, `null` when the request was not authenticated) |
+| `job` | A job reaches `succeeded`, `failed`, `timed_out` or `cancelled` | `job_id`, `task`, `owner`, `job_status`, `queue_ms` (submission to `running`, `null` if no child started it), `run_ms` (`running` to the terminal status, `null` likewise) |
+| `start` | The port is bound and the children are starting | `backend`, `concurrency`, `capacity`, `retention_seconds`, `max_jobs`, `drain_seconds`, `tokens` (how many tokens are configured; never a name or a token) |
+| `drain` | A drain ends, before the worker stops serving | `duration_ms` (from the signal), `running` (jobs still running when it ended, which the stop then cancels), `interrupted` (a second signal ended it) |
+| `stop` | The worker has stopped its children and closed the job table | `cancelled` (unfinished jobs the stop ended as `cancelled`) |
+
+`level` is `warning` for a request answered 5xx, a job that ended `failed` or `timed_out`, a drain that left jobs running and a stop that cancelled any; otherwise `info`. A 503 for a full connection budget is written without reading anything, so its `method` is `null`, its `route` `other` and its `duration_ms` 0. The timings are measured by the parent process, which reads a child's messages every 10 ms or so, so `queue_ms` and `run_ms` can each be off by that much. A job read back from `BRIDGE_STATE_DIR` ended in an earlier process and writes no line.

docs/security.md

@@ -13,7 +13,7 @@ This experimental service is designed for trusted application-to-service traffic
 - Redaction is assistive, not a compliance control. The rules find only the structured identifiers they recognise, and the optional named-entity models were trained on English news, so their recall on names from other domains or languages is lower and unmeasured here; review redacted output before treating it as free of personal data. The model files are third-party ONNX conversions of the original weights, pinned by revision and hash but not signed by the original author.
 - The MCP server is a client of this service for an AI agent over stdio, where there is no authentication: the host that launches it inherits its trust, and it holds the token from its environment and never returns it. Running it over HTTP or SSE would be a new authorisation surface that the bearer token does not cover; it is out of scope. An agent can be prompt-injected and can then fill a worker's capacity, so point the MCP server at a dedicated worker, never at one serving a production application; compose's `mcp` and `mcp-model` each have their own. It reads files only under `BRIDGE_MCP_ROOT` and writes none; snippets it returns are the agent's own file content and enter the agent's context like any file it reads. Index files built for `bridge_search` are derived data: `index.json` holds every chunk's text verbatim and `vectors.f32` holds vectors that can reveal it, so keep them with the same care as their sources. The builder runs with the service token like the PHP client and is the only component that writes, into the directory the operator names.
 - `GET /metrics` reveals aggregate numbers only: how many jobs of each task were submitted, refused for capacity and ended in each terminal status, how many are queued and running, the pool's size and readiness, the concurrency and capacity settings, the backend name, and histograms of job and queue durations per task. It never reveals a job ID, idempotency key, input, result, error message, model path or the token; its label values come from fixed sets, never from a request. Counts and timings still describe the traffic (how busy the service is, which tasks run, how long they take), so the endpoint is behind the same service token as every route: scrape it from inside the private network with that token, never through a public route. How often it is scraped is the operator's concern; a scrape copies a few counters under the store's lock and formats them outside it.
-- Access logs are disabled to avoid accidentally recording identifiers and inputs. Internal exceptions become generic task errors. This is not a full observability or compliance solution.
+- The worker writes no log unless `BRIDGE_LOG=json` is set. Then it writes JSON lines on stderr for each request (method, route template, status, duration, the token's name), each job that ends (job ID, task, the token's name, terminal status, queue and run times) and the start, drain and stop (the backend, the numeric limits and how many tokens are configured, how many jobs a drain or stop cut short). It never writes an input, result, header, path or query string, idempotency key, token, error message or exception text: the formatter keeps only its fixed keys and checks each value against a fixed set, a number, the job ID's 32 hex characters or the token-name pattern, writing `null` otherwise. Job IDs and token names still link requests to clients, and timings still describe the traffic, so keep the log with the same care as the metrics. Internal exceptions become generic task errors. This is not a full observability or compliance solution; [the protocol](protocol.md#logging) has the schema.
 - Cancel/timeout terminates the task process, but cannot roll back previously completed external effects. No task in the prototype modifies an external system.
 - `/healthz` proves HTTP service availability, not model integrity, ability to spawn processes or successful inference. `/readyz` adds that a child process started and loaded the configured backend's models without an error; it does not prove that they infer correctly. An ONNX worker checks before it starts that each model directory holds its tokenizer and model files and refuses to start otherwise; that proves presence, not integrity, which the fetcher's hashes establish. Use a controlled model smoke test for inference validation.
 - A drain (the first SIGTERM or SIGINT) keeps the inputs of running jobs in their children until they finish, the deadline passes or a second signal ends it, and keeps every finished result until the process exits. It drops the input of every job still queued at once: the job is failed as `service_restarted` and nothing of it is replayed, so a caller resubmits. Results and inputs are never written anywhere for a later process; with `BRIDGE_STATE_DIR` the job table holds what it always holds (never an input). The process ends with its memory, so after it nothing of a job survives outside that table.