Wingman#7 structured logging baseline

.github/workflows/build.yml

@@ -65,7 +65,7 @@ jobs:
             type=ref,event=branch
             type=semver,pattern={{version}}
             type=semver,pattern={{major}}.{{minor}}
-            type=sha,prefix={{branch}}-
+            type=sha,prefix=sha-
             type=raw,value=latest,enable={{is_default_branch}}
 
       - name: Build and push

backend/app/logging.py

@@ -0,0 +1,21 @@
+"""Settings-based logging setup shared by Wingman's process entrypoints.
+
+Reuse the wide-event formatter so all entrypoints keep the same schema,
+redaction and request correlation. See docs/logging.md.
+"""
+
+from app.config import settings
+from app.logging_config import JsonFormatter, configure_logging as _configure_logging
+
+__all__ = ["JsonFormatter", "configure_logging"]
+
+
+def configure_logging(*, service: str = "wingman-backend") -> None:
+    """Configure stdout logging; repeated calls keep a single root handler."""
+    _configure_logging(
+        level=settings.LOG_LEVEL,
+        fmt=settings.LOG_FORMAT,
+        service=service,
+        environment=settings.ENVIRONMENT,
+        version=settings.APP_VERSION,
+    )

backend/app/main.py

@@ -9,12 +9,14 @@
 import logging
 
 from app.config import settings
+from app.logging import configure_logging
+from app.logging_config import WideEventMiddleware
+
+configure_logging(service="wingman-backend")
+
 from app.database import get_db, init_db, SlackMessage, Document
 from app.rag import rag_engine
 from app.slack_bot import slack_bot
-from app.logging_config import WideEventMiddleware, configure_logging
-
-configure_logging(settings.LOG_LEVEL, settings.LOG_FORMAT, "wingman-backend", settings.ENVIRONMENT, settings.APP_VERSION)
 
 logger = logging.getLogger(__name__)
 

backend/app/slack_bot.py

@@ -7,9 +7,6 @@
 
 import httpx
 from app.config import settings
-from app.logging_config import configure_logging
-
-configure_logging(settings.LOG_LEVEL, settings.LOG_FORMAT, "wingman-bot", settings.ENVIRONMENT, settings.APP_VERSION)
 from app.database import Document, SessionLocal, SlackMessage
 from app.rag import rag_engine
 from slack_bolt import App

backend/run_bot.py

@@ -2,10 +2,9 @@
 Script to run the Slack bot
 """
 import logging
-from app.config import settings
-from app.logging_config import configure_logging
+from app.logging import configure_logging
 
-configure_logging(settings.LOG_LEVEL, settings.LOG_FORMAT, "wingman-bot", settings.ENVIRONMENT, settings.APP_VERSION)
+configure_logging(service="wingman-bot")
 from app.slack_bot import slack_bot
 from app.database import init_db
 

backend/tests/test_logging.py

@@ -0,0 +1,105 @@
+"""Check process logging setup without changing pytest's own handlers."""
+
+import json
+import os
+import subprocess
+import sys
+from datetime import datetime
+
+import pytest
+
+
+def run_logging(code: str, **settings: str) -> subprocess.CompletedProcess[str]:
+    """Run a logging check in an isolated process with explicit settings."""
+    return subprocess.run(
+        [sys.executable, "-c", code],
+        env={**os.environ, **settings},
+        capture_output=True,
+        text=True,
+        check=True,
+    )
+
+
+@pytest.mark.parametrize("service", ["wingman-backend", "wingman-bot"])
+def test_json_stdout_preserves_controls_and_avoids_duplicate_handlers(service: str) -> None:
+    """Emit parseable, redacted records once with the correct service metadata."""
+    result = run_logging(
+        f"""
+import logging
+from app.logging import configure_logging
+from app.logging_config import request_id_var
+configure_logging(service={service!r})
+configure_logging(service={service!r})
+request_id_var.set("smoke-123")
+logger = logging.getLogger("logging.smoke")
+logger.debug("filtered")
+logger.info("Indexed %s", "file", extra={{"file_type": "pdf", "api_token": "secret"}})
+try:
+    raise ValueError("contact me@example.org")
+except ValueError:
+    logger.exception("Index failed")
+""",
+        LOG_FORMAT="json", LOG_LEVEL="INFO", ENVIRONMENT="test", APP_VERSION="1.2.3",
+    )
+    records = [json.loads(line) for line in result.stdout.splitlines()]
+    assert len(records) == 2
+    info, error = records
+    assert info["service_name"] == service
+    assert info["environment"] == "test" and info["service_version"] == "1.2.3"
+    assert datetime.fromisoformat(info["timestamp"]).utcoffset().total_seconds() == 0
+    assert info["message"] == "Indexed file" and info["file_type"] == "pdf"
+    assert info["request_id"] == "smoke-123" and info["api_token"] == "[REDACTED]"
+    assert error["level"] == "ERROR" and error["error_class"] == "ValueError"
+    assert error["error_message"] == "contact [REDACTED]"
+    assert error["error_stack_hash"] and "exception" not in error
+    assert not result.stderr
+
+
+def test_text_format_and_configured_level() -> None:
+    """Honor the selected text format and minimum severity."""
+    result = run_logging(
+        """
+import logging
+from app.logging import configure_logging
+configure_logging()
+logger = logging.getLogger("logging.smoke")
+logger.info("filtered")
+logger.warning("visible")
+""",
+        LOG_FORMAT="text", LOG_LEVEL="WARNING",
+    )
+    assert len(result.stdout.splitlines()) == 1
+    assert "WARNING logging.smoke visible" in result.stdout
+    assert not result.stderr
+
+
+def test_api_keeps_backend_service_when_importing_bot() -> None:
+    """Keep the API service label after importing the Slack bot singleton."""
+    result = run_logging(
+        """
+import sys
+from types import ModuleType
+from unittest.mock import patch
+from fastapi.testclient import TestClient
+
+# The health endpoint does not use RAG or Slack; keep this check offline.
+rag = ModuleType("app.rag")
+rag.rag_engine = object()
+sys.modules["app.rag"] = rag
+with patch("slack_sdk.WebClient.auth_test", return_value={
+    "ok": True, "bot_id": "BTEST", "user_id": "UTEST", "team_id": "TTEST"
+}):
+    from app.main import app
+response = TestClient(app).get("/health", headers={"x-request-id": "health-smoke"})
+assert response.status_code == 200
+""",
+        LOG_FORMAT="json", LOG_LEVEL="INFO", DATABASE_URL="sqlite://",
+        SLACK_BOT_TOKEN="xoxb-test", SLACK_SIGNING_SECRET="test",
+    )
+    records = [json.loads(line) for line in result.stdout.splitlines()]
+    events = [record for record in records if record["event_type"] == "http_request"]
+    assert len(events) == 1
+    event = events[0]
+    assert event["service_name"] == "wingman-backend"
+    assert event["request_id"] == "health-smoke" and event["status_code"] == 200
+    assert event["duration_ms"] >= 0

docs/logging.md

@@ -2,8 +2,13 @@
 
 ## Schema
 
-All services emit one JSON object per line to **stdout** via
-`backend/app/logging_config.py` (`JsonFormatter`, `configure_logging`).
+The `backend` (FastAPI) and `bot` (Slack Bolt) services share the `/backend`
+codebase and emit one JSON object per line to **stdout** by default.
+`backend/app/logging.py` provides settings-based `configure_logging()` and
+re-exports `JsonFormatter`; both use the implementation in
+`backend/app/logging_config.py`, including its redaction and request correlation.
+
+Tracked in [echohello-dev/wingman#7](https://github.com/echohello-dev/wingman/issues/7).
 
 | Field | Notes |
 |---|---|
@@ -19,6 +24,15 @@ looks sensitive (token/secret/password/api-key/authorization/cookie/
 credential/email/…), in which case the value is `[REDACTED]` — fail-closed.
 Slack/OpenAI tokens, card numbers and emails in message text are scrubbed.
 
+Example (ordinary log with structured extras):
+
+```json
+{"timestamp":"2026-08-18T01:23:45.123456+00:00","level":"INFO","service_name":"wingman-bot","environment":"development","service_version":"0.1.0","logger":"app.slack_bot","message":"Indexed file","event_type":"log","request_id":null,"trace_id":null,"file_type":"pdf"}
+```
+
+Extra fields appear at the top level. Exceptions use redacted error fields
+and a stack hash, rather than a full traceback.
+
 Not yet emitted (needs instrumentation, not just config): `user_id`/
 `org_id` (hashed), `db_queries`, `external_calls`, `cache_hit`,
 `retries_count`, resource usage. Do not claim these in assessments yet.
@@ -31,6 +45,14 @@ Not yet emitted (needs instrumentation, not just config): `user_id`/
 | Local dev stdout | Actual | Terminal only, not retained |
 | Any central sink (CloudWatch/Datadog/ELK/S3) | **Not configured** — no shipper, credentials, or IaC in this repo | None — cannot be evidenced |
 
+Other Compose services are outside this Python schema: `frontend` emits
+Next.js logs; `postgres` and `chroma` use their image defaults. No explicit
+rotation or retention is configured for them in `compose.yaml` either.
+The host's Docker daemon may override its default logging driver or rotation;
+verify the deployed host before claiming a retention period. With Docker's
+default `json-file` driver, logs grow without a size bound unless rotation is
+configured, and local container logs do not survive container removal.
+
 Assumed baseline to adopt (not yet in force): hot 7d, warm 30d,
 cold 90d+ in a central sink, per the wide-event tiering model.
 Until a sink is deployed, assessment evidence is limited to
@@ -41,8 +63,31 @@ Until a sink is deployed, assessment evidence is limited to
 `LOG_LEVEL`, `LOG_FORMAT=json|text`, `ENVIRONMENT`,
 `LOG_WIDE_EVENT_SAMPLE_RATE` (default `1.0`; errors and
 `duration_ms > LOG_SLOW_MS` always kept), `LOG_SLOW_MS` — see
-`.env.example`. Wide events are emitted fire-and-forget on the logging
-handler; they never block the response beyond stdlib stream write.
+`.env.example`. Wide events use synchronous stdlib stream writes in the
+request's finalizer. A slow stdout destination can delay request completion;
+there is no background queue or log shipper in this baseline.
+
+| Setting | Default | Purpose |
+|---|---|---|
+| `LOG_LEVEL` | `INFO` | Minimum root logger level |
+| `LOG_FORMAT` | `json` | JSON lines; `text` for local development |
+| `ENVIRONMENT` | `development` | Environment label |
+| `LOG_WIDE_EVENT_SAMPLE_RATE` | `1.0` | Fraction of ordinary HTTP requests logged |
+| `LOG_SLOW_MS` | `1000` | Slow-request threshold in milliseconds |
+
+### Application conventions
+
+- Call `from app.logging import configure_logging` at process startup before
+  importing application singletons. Use `configure_logging(service="wingman-backend")`
+  in `app/main.py` and `configure_logging(service="wingman-bot")` in `run_bot.py`.
+  Repeated calls replace the root handler rather than adding duplicate output.
+- Library modules, including `app/slack_bot.py`, only obtain a logger with
+  `logging.getLogger(__name__)`; they do not configure the process logger.
+- Attach structured fields with `extra=`, for example
+  `logger.info("Indexed file", extra={"file_type": "pdf"})`.
+- Never log credentials or full Slack event/message payloads. Pattern redaction
+  is a backstop, not proof that arbitrary user content is safe. Existing payload
+  logging still needs review before claiming comprehensive sensitive-data controls.
 
 ## Needed for stronger assessment evidence
 
@@ -51,3 +96,5 @@ handler; they never block the response beyond stdlib stream write.
 3. Instrument DB/external-call counters and hashed user/org IDs into the wide event.
 4. Alert/dashboard on error rate (`status_code>=500`) and p95 `duration_ms` by route.
 5. Periodic access review and retention-deletion proof for the sink.
+6. Review existing payload logging and add evidence that secrets and user content
+   are excluded; document which operators can access each environment's logs.

mise.toml

@@ -51,7 +51,7 @@ run = "docker compose ps"
 [tasks.test-backend]
 description = "Run backend tests"
 dir = "backend"
-run = "uv run pytest tests/test_file_extraction_units.py -v"
+run = "uv run pytest tests/test_file_extraction_units.py tests/test_logging_config.py tests/test_logging.py -v"
 
 [tasks.migrate]
 description = "Run database migrations (upgrade to latest)"