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.

backend/tests/test_logging_formatter.py

@@ -0,0 +1,165 @@
+"""SP18 — JsonFormatter + CycloneDevFormatter tests.
+
+Covers the structural shape of log records, exception handling,
+and the ``extra`` kwarg passthrough.
+"""
+from __future__ import annotations
+
+import io
+import json
+import logging
+
+import pytest
+
+from cyclone.logging_config import (
+    CycloneDevFormatter,
+    JsonFormatter,
+    setup_logging,
+)
+
+
+def _make_record(
+    msg: str = "hello",
+    args: tuple = (),
+    level: int = logging.INFO,
+    name: str = "test.logger",
+    extras: dict | None = None,
+    exc_info=None,
+) -> logging.LogRecord:
+    record = logging.getLogger(name).makeRecord(
+        name=name,
+        level=level,
+        fn="t.py",
+        lno=1,
+        msg=msg,
+        args=args,
+        exc_info=exc_info,
+    )
+    if extras:
+        for k, v in extras.items():
+            setattr(record, k, v)
+    return record
+
+
+# ---------------------------------------------------------------------------
+# JsonFormatter
+# ---------------------------------------------------------------------------
+
+
+def test_json_formatter_basic_shape():
+    f = JsonFormatter()
+    line = f.format(_make_record(msg="hello %s", args=("cyclone",)))
+    parsed = json.loads(line)
+    assert parsed["level"] == "INFO"
+    assert parsed["logger"] == "test.logger"
+    assert parsed["msg"] == "hello cyclone"
+    assert "ts" in parsed
+    # ts must be ISO 8601 with milliseconds + Z suffix.
+    assert parsed["ts"].endswith("Z") or "+" in parsed["ts"]
+
+
+def test_json_formatter_includes_extras():
+    f = JsonFormatter()
+    line = f.format(_make_record(
+        msg="processed",
+        extras={"input_filename": "foo.x12", "parser_kind": "parse_999", "claims": 3},
+    ))
+    parsed = json.loads(line)
+    assert parsed["extra"] == {
+        "input_filename": "foo.x12", "parser_kind": "parse_999", "claims": 3,
+    }
+
+
+def test_json_formatter_handles_exception_info():
+    f = JsonFormatter()
+    try:
+        raise ValueError("boom")
+    except ValueError:
+        import sys
+        rec = _make_record(msg="oops", exc_info=sys.exc_info())
+    line = f.format(rec)
+    parsed = json.loads(line)
+    assert "traceback" in parsed
+    assert "ValueError: boom" in parsed["traceback"]
+
+
+def test_json_formatter_no_extras_key_when_none():
+    f = JsonFormatter()
+    line = f.format(_make_record(msg="plain"))
+    parsed = json.loads(line)
+    assert "extra" not in parsed
+
+
+def test_json_formatter_handles_non_serializable_extras():
+    """Non-JSON-serializable extras go through ``default=str``."""
+    class Opaque:
+        def __str__(self):
+            return "opaque-string"
+    f = JsonFormatter()
+    line = f.format(_make_record(msg="x", extras={"thing": Opaque()}))
+    parsed = json.loads(line)
+    assert parsed["extra"]["thing"] == "opaque-string"
+
+
+def test_json_formatter_preserves_warning_level():
+    f = JsonFormatter()
+    line = f.format(_make_record(msg="careful", level=logging.WARNING))
+    parsed = json.loads(line)
+    assert parsed["level"] == "WARNING"
+
+
+# ---------------------------------------------------------------------------
+# CycloneDevFormatter
+# ---------------------------------------------------------------------------
+
+
+def test_dev_formatter_basic_shape():
+    f = CycloneDevFormatter()
+    line = f.format(_make_record(msg="hello %s", args=("cyclone",)))
+    assert "INFO" in line
+    assert "test.logger" in line
+    assert "hello cyclone" in line
+
+
+def test_dev_formatter_includes_extras():
+    f = CycloneDevFormatter()
+    line = f.format(_make_record(
+        msg="processed",
+        extras={"input_filename": "foo.x12", "claims": 3},
+    ))
+    assert "input_filename='foo.x12'" in line
+    assert "claims=3" in line
+
+
+def test_dev_formatter_handles_exception():
+    f = CycloneDevFormatter()
+    try:
+        raise RuntimeError("nope")
+    except RuntimeError:
+        import sys
+        rec = _make_record(msg="oops", exc_info=sys.exc_info())
+    line = f.format(rec)
+    assert "RuntimeError: nope" in line
+
+
+# ---------------------------------------------------------------------------
+# setup_logging (light — deeper coverage in test_logging_setup.py)
+# ---------------------------------------------------------------------------
+
+
+def test_setup_logging_attaches_handler_to_root():
+    setup_logging(level="DEBUG", json_format=True)
+    root = logging.getLogger()
+    assert len(root.handlers) >= 1
+    assert isinstance(root.handlers[0].formatter, JsonFormatter)
+
+
+def test_setup_logging_is_idempotent():
+    """Re-calling clears handlers; the formatter toggle takes effect."""
+    setup_logging(level="INFO", json_format=True)
+    setup_logging(level="INFO", json_format=False)
+    root = logging.getLogger()
+    assert len(root.handlers) == 1
+    assert isinstance(root.handlers[0].formatter, CycloneDevFormatter)
+    # Reset back to JSON for the rest of the test suite.
+    setup_logging(level="INFO", json_format=True)

backend/tests/test_logging_scrubber.py

@@ -0,0 +1,157 @@
+"""SP18 — PII scrubber tests.
+
+Covers each PHI pattern, the false-positive guard, and the
+disable toggle.
+"""
+from __future__ import annotations
+
+import logging
+
+import pytest
+
+from cyclone.logging_config import (
+    PiiScrubber,
+    get_scrubber,
+    setup_logging,
+)
+
+
+def _make_record(msg: str, extras: dict | None = None) -> logging.LogRecord:
+    record = logging.getLogger("test.scrub").makeRecord(
+        name="test.scrub", level=logging.INFO, fn="t.py", lno=1,
+        msg=msg, args=(), exc_info=None,
+    )
+    if extras:
+        for k, v in extras.items():
+            setattr(record, k, v)
+    return record
+
+
+@pytest.fixture(autouse=True)
+def _reset_scrubber():
+    """Make sure the scrubber is enabled + on the root after each test."""
+    yield
+    get_scrubber().enable()
+
+
+# ---------------------------------------------------------------------------
+# NPI
+# ---------------------------------------------------------------------------
+
+
+def test_scrubs_ten_digit_npi_in_message():
+    scrubber = PiiScrubber()
+    rec = _make_record("processed claim with npi 1881068062 ok")
+    assert scrubber.filter(rec) is True
+    assert rec.getMessage() == "processed claim with npi <redacted:npi> ok"
+
+
+def test_scrubs_npi_in_extras():
+    scrubber = PiiScrubber()
+    rec = _make_record("ok", extras={"provider_npi": "1881068062"})
+    scrubber.filter(rec)
+    assert rec.provider_npi == "<redacted:npi>"
+
+
+def test_does_not_scrub_short_numbers():
+    scrubber = PiiScrubber()
+    rec = _make_record("processed 5 claims in 2 batches")
+    scrubber.filter(rec)
+    assert rec.getMessage() == "processed 5 claims in 2 batches"
+
+
+def test_does_not_scrub_eleven_digit_numbers():
+    """11+ digit numbers aren't NPIs — leave them alone."""
+    scrubber = PiiScrubber()
+    rec = _make_record("control number 12345678901")
+    scrubber.filter(rec)
+    assert rec.getMessage() == "control number 12345678901"
+
+
+# ---------------------------------------------------------------------------
+# SSN
+# ---------------------------------------------------------------------------
+
+
+def test_scrubs_dashed_ssn_in_message():
+    scrubber = PiiScrubber()
+    rec = _make_record("ssn=123-45-6789 detected")
+    scrubber.filter(rec)
+    assert rec.getMessage() == "ssn=<redacted:ssn> detected"
+
+
+def test_scrubs_undashed_ssn_at_phrase_boundary():
+    """A bare 9-digit number is ambiguous — we scrub it when followed
+    by whitespace/punctuation/closing paren/brace/comma (so we don't
+    hit claim control numbers or zip codes mid-sentence)."""
+    scrubber = PiiScrubber()
+    rec = _make_record("ssn 123456789 on file")
+    scrubber.filter(rec)
+    assert "<redacted:ssn>" in rec.getMessage()
+
+
+# ---------------------------------------------------------------------------
+# DOB
+# ---------------------------------------------------------------------------
+
+
+def test_scrubs_dob_field():
+    scrubber = PiiScrubber()
+    rec = _make_record("dob=1980-04-12 verified")
+    scrubber.filter(rec)
+    assert rec.getMessage() == "dob=<redacted:dob> verified"
+
+
+def test_scrubs_dob_in_extras():
+    scrubber = PiiScrubber()
+    rec = _make_record("ok", extras={"date_of_birth": "1980-04-12"})
+    scrubber.filter(rec)
+    assert rec.date_of_birth == "<redacted:dob>"
+
+
+def test_does_not_scrub_bare_iso_date():
+    """A YYYY-MM-DD without a dob= prefix isn't necessarily PHI."""
+    scrubber = PiiScrubber()
+    rec = _make_record("parsed at 2026-06-21")
+    scrubber.filter(rec)
+    assert rec.getMessage() == "parsed at 2026-06-21"
+
+
+# ---------------------------------------------------------------------------
+# Patient name
+# ---------------------------------------------------------------------------
+
+
+def test_scrubs_patient_name_field():
+    scrubber = PiiScrubber()
+    rec = _make_record('patient_name="John Doe" verified')
+    scrubber.filter(rec)
+    assert "John Doe" not in rec.getMessage()
+    assert "<redacted:patient_name>" in rec.getMessage()
+
+
+def test_does_not_scrub_random_words():
+    scrubber = PiiScrubber()
+    rec = _make_record("the parser ran successfully")
+    scrubber.filter(rec)
+    assert rec.getMessage() == "the parser ran successfully"
+
+
+# ---------------------------------------------------------------------------
+# Disable toggle
+# ---------------------------------------------------------------------------
+
+
+def test_scrubber_disabled_leaves_message_intact():
+    scrubber = PiiScrubber()
+    scrubber.disable()
+    rec = _make_record("npi 1881068062 ok")
+    scrubber.filter(rec)
+    assert rec.getMessage() == "npi 1881068062 ok"
+
+
+def test_scrubber_does_not_crash_on_unusual_records():
+    """Even with weird attribute combinations the filter returns True."""
+    scrubber = PiiScrubber()
+    rec = _make_record("ok", extras={"weird": object()})
+    assert scrubber.filter(rec) is True

backend/tests/test_logging_setup.py

@@ -0,0 +1,127 @@
+"""SP18 — ``setup_logging`` entry-point tests.
+
+Covers level resolution, handler attachment, env-var overrides, and
+the idempotent re-setup behavior used by the FastAPI lifespan and
+the CLI's ``main()``.
+"""
+from __future__ import annotations
+
+import logging
+import os
+from pathlib import Path
+
+import pytest
+
+from cyclone.logging_config import (
+    CycloneDevFormatter,
+    JsonFormatter,
+    PiiScrubber,
+    setup_logging,
+)
+
+
+@pytest.fixture(autouse=True)
+def _reset_root_logger():
+    """Strip our handlers + filters before each test so setup runs clean."""
+    root = logging.getLogger()
+    for h in list(root.handlers):
+        root.removeHandler(h)
+    for flt in list(root.filters):
+        if isinstance(flt, PiiScrubber):
+            root.removeFilter(flt)
+    yield
+    for h in list(root.handlers):
+        root.removeHandler(h)
+    for flt in list(root.filters):
+        if isinstance(flt, PiiScrubber):
+            root.removeFilter(flt)
+
+
+def test_setup_respects_level_string():
+    setup_logging(level="DEBUG", json_format=True)
+    assert logging.getLogger().level == logging.DEBUG
+    setup_logging(level="WARNING", json_format=True)
+    assert logging.getLogger().level == logging.WARNING
+
+
+def test_setup_attaches_rotating_file_handler(tmp_path: Path):
+    log_file = tmp_path / "cyclone.log"
+    setup_logging(level="INFO", log_file=str(log_file), json_format=True)
+    root = logging.getLogger()
+    assert len(root.handlers) == 1
+    h = root.handlers[0]
+    # RotatingFileHandler has ``baseFilename`` attr.
+    assert hasattr(h, "baseFilename")
+    assert Path(h.baseFilename).name == "cyclone.log"
+
+
+def test_setup_defaults_to_json_formatter():
+    setup_logging(level="INFO")
+    root = logging.getLogger()
+    assert isinstance(root.handlers[0].formatter, JsonFormatter)
+
+
+def test_setup_dev_toggle_uses_dev_formatter():
+    setup_logging(level="INFO", json_format=False)
+    root = logging.getLogger()
+    assert isinstance(root.handlers[0].formatter, CycloneDevFormatter)
+
+
+def test_setup_idempotent_re_setup_replaces_handlers():
+    """Re-calling setup_logging clears the previous handler(s)."""
+    setup_logging(level="INFO", json_format=True)
+    setup_logging(level="DEBUG", json_format=False)
+    root = logging.getLogger()
+    assert len(root.handlers) == 1
+    assert isinstance(root.handlers[0].formatter, CycloneDevFormatter)
+    assert root.level == logging.DEBUG
+
+
+def test_setup_quietens_noisy_third_party_loggers():
+    setup_logging(level="DEBUG", json_format=True)
+    for noisy in ("urllib3", "paramiko", "sqlalchemy.engine"):
+        assert logging.getLogger(noisy).level >= logging.WARNING
+
+
+def test_setup_attaches_pii_scrubber_by_default():
+    setup_logging(level="INFO", json_format=True)
+    root = logging.getLogger()
+    assert any(isinstance(f, PiiScrubber) for f in root.filters)
+
+
+def test_setup_honors_scrub_pii_false():
+    setup_logging(level="INFO", json_format=True, scrub_pii=False)
+    root = logging.getLogger()
+    # Scrubber is still attached but disabled.
+    scrubbers = [f for f in root.filters if isinstance(f, PiiScrubber)]
+    assert len(scrubbers) == 1
+    assert scrubbers[0]._enabled is False  # noqa: SLF001
+
+
+def test_setup_honors_env_var_no_pii_scrub(monkeypatch):
+    monkeypatch.setenv("CYCLONE_LOG_NO_PII_SCRUB", "1")
+    setup_logging(level="INFO", json_format=True)
+    scrubbers = [f for f in logging.getLogger().filters if isinstance(f, PiiScrubber)]
+    assert scrubbers and scrubbers[0]._enabled is False  # noqa: SLF001
+
+
+def test_setup_emits_json_to_stderr_by_default(caplog):
+    """Records emitted after setup flow through JsonFormatter."""
+    setup_logging(level="INFO", json_format=True)
+    logger = logging.getLogger("cyclone.test_setup")
+    logger.info("hello %s", "world", extra={"x": 1})
+    # Cyclone attaches the handler to root, not the named logger; caplog
+    # won't capture unless we propagate (which is the default).
+    # Just assert the handler is on root and would format correctly.
+    root = logging.getLogger()
+    h = root.handlers[0]
+    record = logger.makeRecord(
+        name="cyclone.test_setup", level=logging.INFO, fn="t.py", lno=1,
+        msg="hello %s", args=("world",), exc_info=None,
+    )
+    record.x = 1
+    formatted = h.formatter.format(record)
+    import json as _json
+    parsed = _json.loads(formatted)
+    assert parsed["msg"] == "hello world"
+    assert parsed["extra"]["x"] == 1