Tyler
47e0f80786
Cyclone previously emitted stdlib default-formatted log lines that
operators couldn't parse with anything beyond grep. SP18 replaces
that with:
- JsonFormatter: newline-delimited JSON, ISO-8601 ms timestamps,
structured "extra" dict, exception tracebacks serialized as a
single string.
- CycloneDevFormatter: tabular format for tail -f in dev.
- PiiScrubber: logging.Filter that redacts NPIs, SSNs, DOBs,
patient names — both inline in the message ("npi 1881068062")
and via PHI-keyed extras ({"dob": "1980-04-12"}).
- setup_logging(): idempotent entry point used by the API lifespan
and CLI main; respects CYCLONE_LOG_LEVEL/FILE/JSON/NO_PII_SCRUB.
- CLI --log-format=json|dev + --log-file=… flags.
- Migrate 9 highest-value log sites in scheduler/backup_scheduler/
backup_service to use extra={...} (input_filename, claims, parser,
backup_id, db_fingerprint, etc.).
34 new tests (test_logging_formatter + test_logging_scrubber +
test_logging_setup). All 867 backend tests pass.
133 lines
5.5 KiB
Markdown
133 lines
5.5 KiB
Markdown
# SP18 — Structured JSON Logging
|
||
|
||
**Date:** 2026-06-21
|
||
**Branch:** `sp18-structured-logging`
|
||
**Status:** Shipped
|
||
**Scope:** Backend only. No frontend changes.
|
||
|
||
---
|
||
|
||
## 1. Why this exists
|
||
|
||
Cyclone has ~150 `logging.getLogger(__name__).*` call sites and
|
||
zero of them are structured. The format is the stdlib default — a
|
||
human-readable line like `2026-06-21 15:30:00,123 INFO
|
||
cyclone.scheduler: Processed inbound foo.x12: parser=parse_999 claims=3`
|
||
— which is fine for `tail -f` in dev but unparseable for anything an
|
||
operator actually wants to do with logs:
|
||
|
||
* **Find all errors in the last 24h.** `grep` for `ERROR` and you get
|
||
the lines, but not the tracebacks, not the related claim IDs, not
|
||
the durations.
|
||
* **Correlate scheduler ticks with API requests.** Impossible without
|
||
a request/correlation id in every line.
|
||
* **Detect PII leaks.** No scrubbing means a single accidental
|
||
`log.info("claim=%s", claim)` can dump PHI to stderr and the
|
||
README won't catch it.
|
||
|
||
The completeness review calls this out as gap #5 (`no structured
|
||
logging`).
|
||
|
||
SP18 fixes this by adding a `JsonFormatter` that emits
|
||
newline-delimited JSON, a `PiiScrubber` filter that strips obvious
|
||
PHI patterns (NPIs, claim control numbers, patient names), and a
|
||
`setup_logging(level, log_file, json_format)` entry point that the
|
||
CLI + API lifespan call once at startup.
|
||
|
||
## 2. Output format
|
||
|
||
Default (json_format=True):
|
||
|
||
```json
|
||
{"ts": "2026-06-21T15:30:00.123Z", "level": "INFO", "logger": "cyclone.scheduler", "msg": "Processed inbound foo.x12", "extra": {"parser": "parse_999", "claims": 3}}
|
||
{"ts": "2026-06-21T15:30:00.456Z", "level": "ERROR", "logger": "cyclone.api", "msg": "backup failed", "extra": {"reason": "BackupError: no passphrase"}}
|
||
```
|
||
|
||
Optional (json_format=False, the dev-friendly format):
|
||
|
||
```
|
||
2026-06-21T15:30:00.123Z INFO cyclone.scheduler Processed inbound foo.x12 parser=parse_999 claims=3
|
||
```
|
||
|
||
The dev format is the `CycloneDevFormatter` — same fields, tabular.
|
||
Useful when `tail -f`-ing the API in dev.
|
||
|
||
## 3. PII scrubbing
|
||
|
||
The `PiiScrubber` is a logging `Filter` that walks the log record's
|
||
message + extra fields and replaces known PHI patterns with
|
||
`<redacted:npi>` etc.:
|
||
|
||
| Pattern | Replacement |
|
||
|---------|-------------|
|
||
| `\b\d{10}\b` (NPI) | `<redacted:npi>` |
|
||
| `\b\d{9}\b` (claim control number with leading zeros — risky; conservative) | not redacted by default |
|
||
| `(?i)patient[_ ]?name[:=]\s*\S+` | `<redacted:patient_name>` |
|
||
| `(?i)ssn[:=]\s*\d{3}-?\d{2}-?\d{4}` | `<redacted:ssn>` |
|
||
| `(?i)dob[:=]\s*\d{4}-\d{2}-\d{2}` | `<redacted:dob>` |
|
||
|
||
The default scrubber is conservative — we redact the unambiguous
|
||
patterns only. False positives are not free: a redacted NPI in an
|
||
operator's diagnostic dump is worse than a leaky one. The scrubber
|
||
can be disabled (`setup_logging(scrub_pii=False)`) for tests.
|
||
|
||
## 4. Files
|
||
|
||
* `cyclone.logging_config` — new module (~200 LOC).
|
||
* `JsonFormatter` — `logging.Formatter` subclass that JSON-encodes the record.
|
||
* `CycloneDevFormatter` — `logging.Formatter` subclass, tabular.
|
||
* `PiiScrubber` — `logging.Filter` subclass, regex rewriter.
|
||
* `setup_logging(level, log_file, json_format, scrub_pii)` — entry point.
|
||
* CLI: every `click.command` calls `setup_logging(log_level)` first
|
||
(the existing `--log-level` flag already exists on `parse-837` and
|
||
`parse-835`; just wire it to the new module).
|
||
* API: the FastAPI lifespan calls `setup_logging(level=os.environ.get("CYCLONE_LOG_LEVEL", "INFO"))` before any other setup.
|
||
* Scheduler: scheduler tick logs flow through the same root logger
|
||
so the backup/MFT scheduler ticks are visible in the log stream
|
||
with structured `extra={...}`.
|
||
|
||
## 5. Operator surface
|
||
|
||
| Env var | Default | Meaning |
|
||
|---------|---------|---------|
|
||
| `CYCLONE_LOG_LEVEL` | `INFO` | Root logger level. DEBUG for troubleshooting, WARNING to quiet. |
|
||
| `CYCLONE_LOG_FILE` | (none) | If set, write to this path via `RotatingFileHandler` (10 MB × 5 backups). |
|
||
| `CYCLONE_LOG_JSON` | `true` | If `false`, use the dev formatter. |
|
||
| `CYCLONE_LOG_NO_PII_SCRUB` | (none) | If set, disable PII scrubbing (tests / forensic mode). |
|
||
|
||
CLI: existing `--log-level` flag on `parse-837` / `parse-835` now
|
||
also accepts the format choice (JSON is default; pass
|
||
`--log-format=dev` for the tabular form).
|
||
|
||
## 6. Migration strategy
|
||
|
||
SP18 does **not** rewrite every log call. It:
|
||
|
||
1. Adds the formatter + filter to the root logger.
|
||
2. Migrates the ~25 highest-value log sites to use `extra={...}`
|
||
for structured fields (e.g. `log.info("processed inbound",
|
||
extra={"filename": f.name, "parser": "parse_999", "claims": 3})`
|
||
instead of f-string concatenation).
|
||
3. Keeps backward compatibility — `log.info("foo %s", x)` still works.
|
||
|
||
This is a deliberate scope cut. A "rewrite every log call" SP would
|
||
be 2000 lines of churn with no new surface.
|
||
|
||
## 7. Tests
|
||
|
||
* `test_logging_formatter.py` — 6 tests (JSON shape, dev format, level preservation, exception info, extra fields, missing extras).
|
||
* `test_logging_scrubber.py` — 6 tests (NPI / SSN / DOB / patient name scrubbing, no false positives, scrubber disabled).
|
||
* `test_logging_setup.py` — 5 tests (level respected, file handler attached, JSON default, dev toggle, idempotent re-setup).
|
||
|
||
Total: 17 new tests.
|
||
|
||
## 8. Out of scope
|
||
|
||
* A real log aggregator (Loki / ELK / Vector). The JSON format is
|
||
aggregator-friendly; the actual shipping is the operator's job.
|
||
* Per-logger log levels via config file. `CYCLONE_LOG_LEVEL` is a
|
||
single root level for v1; per-logger override via env is a future
|
||
enhancement.
|
||
* OpenTelemetry / Prometheus instrumentation. That's a different
|
||
SP (observability) for later.
|