Files
cyclone/docs/superpowers/specs/2026-06-21-cyclone-structured-logging-design.md
T
Tyler 47e0f80786 feat(sp18): structured JSON logging + PII scrubber
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.
2026-06-21 09:59:34 -06:00

5.5 KiB
Raw Blame History

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):

{"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).
    • JsonFormatterlogging.Formatter subclass that JSON-encodes the record.
    • CycloneDevFormatterlogging.Formatter subclass, tabular.
    • PiiScrubberlogging.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.