feat(logging): structured wide-event logging baseline

.env.example

@@ -145,3 +145,10 @@ PORT=8000
 
 # Frontend API URL
 NEXT_PUBLIC_API_URL=http://localhost:8000
+
+# Logging (structured JSON wide events to stdout; see docs/logging.md)
+LOG_LEVEL=INFO
+LOG_FORMAT=json
+ENVIRONMENT=development
+LOG_WIDE_EVENT_SAMPLE_RATE=1.0
+LOG_SLOW_MS=1000

backend/app/config.py

@@ -15,6 +15,11 @@ class Settings(BaseSettings):
     APP_NAME: str = "Wingman"
     APP_VERSION: str = "0.1.0"
     DEBUG: bool = False
+    ENVIRONMENT: str = "development"
+    LOG_LEVEL: str = "INFO"
+    LOG_FORMAT: str = "json"  # json | text
+    LOG_WIDE_EVENT_SAMPLE_RATE: float = 1.0
+    LOG_SLOW_MS: float = 1000
 
     # Server
     HOST: str = "0.0.0.0"

backend/app/logging_config.py

@@ -0,0 +1,137 @@
+"""Structured (JSON) wide-event logging baseline. Stdlib only.
+
+Schema, destinations and retention: see docs/logging.md.
+One wide event per HTTP request (``event_type="http_request"``) plus
+ordinary structured logs for exceptions/lifecycle. Sensitive values are
+redacted fail-closed: any field whose normalised name looks sensitive
+is dropped, and known secret/PII patterns are scrubbed from strings.
+"""
+from __future__ import annotations
+
+import contextvars
+import hashlib
+import json
+import logging
+import random
+import re
+import sys
+import time
+import uuid
+from datetime import datetime, timezone
+
+request_id_var: contextvars.ContextVar[str | None] = contextvars.ContextVar("request_id", default=None)
+trace_id_var: contextvars.ContextVar[str | None] = contextvars.ContextVar("trace_id", default=None)
+
+_SENSITIVE = ("token", "secret", "password", "passwd", "apikey", "authorization",
+              "cookie", "credential", "privatekey", "sessionid", "email")
+_PATTERNS = [
+    re.compile(r"\b[A-Za-z0-9._%+-]+@[A-Za-z0-9.-]+\.[A-Za-z]{2,}\b"),
+    re.compile(r"\bxox[baprs]-[A-Za-z0-9-]+\b"),
+    re.compile(r"\bsk-[A-Za-z0-9_-]{8,}\b"),
+    re.compile(r"\b\d{4}[-\s]?\d{4}[-\s]?\d{4}[-\s]?\d{4}\b"),
+]
+REDACTED = "[REDACTED]"
+_RESERVED = set(logging.LogRecord("", 0, "", 0, "", (), None).__dict__) | {"message", "asctime", "taskName"}
+
+
+def _is_sensitive(key: str) -> bool:
+    norm = re.sub(r"[^a-z0-9]", "", key.lower())
+    return any(s in norm for s in _SENSITIVE)
+
+
+def redact(value):
+    """Redact by field meaning; unknown string content is pattern-scrubbed."""
+    if isinstance(value, dict):
+        return {k: (REDACTED if _is_sensitive(str(k)) else redact(v)) for k, v in value.items()}
+    if isinstance(value, (list, tuple)):
+        return [redact(v) for v in value]
+    if isinstance(value, str):
+        out = value
+        for p in _PATTERNS:
+            out = p.sub(REDACTED, out)
+        return out[:2000]
+    return value
+
+
+def hash_value(value: str | None) -> str | None:
+    return None if not value else hashlib.sha256(value.encode()).hexdigest()[:16]
+
+
+class JsonFormatter(logging.Formatter):
+    def __init__(self, service: str = "wingman-backend", environment: str = "development", version: str = "0.1.0"):
+        super().__init__()
+        self.service, self.environment, self.version = service, environment, version
+
+    def format(self, record: logging.LogRecord) -> str:
+        payload = {
+            "timestamp": datetime.fromtimestamp(record.created, timezone.utc).isoformat(),
+            "level": record.levelname,
+            "service_name": self.service,
+            "environment": self.environment,
+            "service_version": self.version,
+            "logger": record.name,
+            "message": redact(record.getMessage()),
+            "event_type": getattr(record, "event_type", "log"),
+            "request_id": getattr(record, "request_id", None) or request_id_var.get(),
+            "trace_id": getattr(record, "trace_id", None) or trace_id_var.get(),
+        }
+        for k, v in record.__dict__.items():
+            if k not in _RESERVED and k not in payload and not k.startswith("_"):
+                payload[k] = REDACTED if _is_sensitive(k) else redact(v)
+        if record.exc_info and record.exc_info[0]:
+            exc = record.exc_info[1]
+            payload["error_class"] = record.exc_info[0].__name__
+            payload["error_message"] = redact(str(exc)) if exc else None
+            payload["error_stack_hash"] = hash_value("".join(
+                line.rsplit(":", 1)[0] for line in self.formatException(record.exc_info).splitlines()))
+        return json.dumps(payload, default=str)
+
+
+def configure_logging(level: str = "INFO", fmt: str = "json", service: str = "wingman-backend",
+                      environment: str = "development", version: str = "0.1.0") -> None:
+    handler = logging.StreamHandler(sys.stdout)
+    handler.setFormatter(JsonFormatter(service, environment, version) if fmt.lower() == "json"
+                         else logging.Formatter("%(asctime)s %(levelname)s %(name)s %(message)s"))
+    root = logging.getLogger()
+    root.handlers[:] = [handler]
+    root.setLevel(level.upper())
+
+
+class WideEventMiddleware:
+    """Pure-ASGI: emits one wide event per HTTP request, non-blocking."""
+
+    def __init__(self, app, logger_name="wingman.wide_event", sample_rate: float = 1.0, slow_ms: float = 1000):
+        self.app, self.sample_rate, self.slow_ms = app, sample_rate, slow_ms
+        self.log = logging.getLogger(logger_name)
+
+    async def __call__(self, scope, receive, send):
+        if scope["type"] != "http":
+            return await self.app(scope, receive, send)
+        rid = next((v.decode() for k, v in scope.get("headers", []) if k == b"x-request-id"), None) or uuid.uuid4().hex
+        tokens = (request_id_var.set(rid), trace_id_var.set(rid))
+        start, status, error = time.perf_counter(), 500, None
+
+        async def wrapped(message):
+            nonlocal status
+            if message["type"] == "http.response.start":
+                status = message["status"]
+            await send(message)
+
+        try:
+            await self.app(scope, receive, wrapped)
+        except Exception as exc:  # record, then preserve framework handling
+            error = exc
+            raise
+        finally:
+            duration = round((time.perf_counter() - start) * 1000, 2)
+            keep = error is not None or status >= 500 or duration > self.slow_ms or random.random() < self.sample_rate
+            if keep:
+                self.log.info("http_request", extra={
+                    "event_type": "http_request", "request_id": rid, "trace_id": rid,
+                    "request_method": scope.get("method"), "request_path": scope.get("path"),
+                    "route": scope.get("path"), "status_code": status, "duration_ms": duration,
+                    "error_class": type(error).__name__ if error else None,
+                    "error_message": redact(str(error)) if error else None,
+                    "sample_reason": "ERROR" if (error or status >= 500) else "SLOW" if duration > self.slow_ms else "RANDOM",
+                })
+            request_id_var.reset(tokens[0]); trace_id_var.reset(tokens[1])

backend/app/main.py

@@ -12,8 +12,10 @@
 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)
 
-logging.basicConfig(level=logging.INFO)
 logger = logging.getLogger(__name__)
 
 # Create FastAPI app
@@ -23,6 +25,8 @@
     description="Slack Support Assistant with RAG capabilities"
 )
 
+app.add_middleware(WideEventMiddleware, sample_rate=settings.LOG_WIDE_EVENT_SAMPLE_RATE, slow_ms=settings.LOG_SLOW_MS)
+
 # Configure CORS
 app.add_middleware(
     CORSMiddleware,

backend/app/slack_bot.py

@@ -7,6 +7,9 @@
 
 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
@@ -18,7 +21,6 @@
     PlanUpdateChunk,
 )
 
-logging.basicConfig(level=logging.INFO)
 logger = logging.getLogger(__name__)
 
 

backend/app/vector_store.py

@@ -7,6 +7,9 @@
 from langchain_openai import OpenAIEmbeddings
 from typing import List, Dict, Any
 from app.config import settings
+import logging
+
+logger = logging.getLogger(__name__)
 
 
 class VectorStore:
@@ -41,7 +44,7 @@ def _ensure_initialized(self):
             self._init_vector_store()
             self._initialized = True
         except Exception as e:
-            print(f"Error initializing vector store: {e}")
+            logger.error("Error initializing vector store: %s", e)
             raise
 
     def _init_vector_store(self):
@@ -53,7 +56,7 @@ def _init_vector_store(self):
                 embedding_function=self.embeddings
             )
         except Exception as e:
-            print(f"Error initializing vector store: {e}")
+            logger.error("Error initializing vector store: %s", e)
             raise
 
     def add_documents(self, texts: List[str], metadatas: List[Dict[str, Any]] = None):
@@ -87,7 +90,7 @@ def delete_collection(self):
         try:
             self.client.delete_collection(name=self.collection_name)
         except Exception as e:
-            print(f"Error deleting collection: {e}")
+            logger.error("Error deleting collection: %s", e)
 
 
 # Global instance

backend/run_bot.py

@@ -2,10 +2,13 @@
 Script to run the Slack bot
 """
 import logging
+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.slack_bot import slack_bot
 from app.database import init_db
 
-logging.basicConfig(level=logging.INFO)
 logger = logging.getLogger(__name__)
 
 if __name__ == "__main__":

backend/tests/test_logging_config.py

@@ -0,0 +1,35 @@
+import json, logging
+import pytest
+from app.logging_config import JsonFormatter, WideEventMiddleware, redact
+
+def fmt_record(msg="hi %s", args=("x",), **extra):
+    r = logging.LogRecord("t", logging.INFO, __file__, 1, msg, args, None)
+    for k, v in extra.items(): setattr(r, k, v)
+    return json.loads(JsonFormatter().format(r))
+
+def test_json_schema_and_redaction_variants():
+    out = fmt_record(api_token="abc", slack_bot_token="xoxb-1", note="mail a@b.com xoxb-secret")
+    assert out["service_name"] and out["timestamp"] and out["level"] == "INFO"
+    assert out["api_token"] == "[REDACTED]" and out["slack_bot_token"] == "[REDACTED]"
+    assert "a@b.com" not in out["message"] and "xoxb-secret" not in out["message"]
+    assert redact("contact me@example.org") == "contact [REDACTED]"
+    # unenumerated long-form variant must not pass through
+    assert redact({"client_secret_value": "s"})["client_secret_value"] == "[REDACTED]"
+
+def test_error_hash_not_stack():
+    try: raise ValueError("bad a@b.com")
+    except ValueError:
+        import sys; r = logging.LogRecord("t", logging.ERROR, __file__, 1, "fail", (), sys.exc_info())
+    out = json.loads(JsonFormatter().format(r))
+    assert out["error_class"] == "ValueError" and out["error_stack_hash"] and "a@b.com" not in out["error_message"]
+
+@pytest.mark.asyncio
+async def test_wide_event_one_per_request(caplog):
+    async def app(scope, receive, send):
+        await send({"type": "http.response.start", "status": 200, "headers": []})
+        await send({"type": "http.response.body", "body": b"ok"})
+    async def send(m): pass
+    with caplog.at_level(logging.INFO, logger="wingman.wide_event"):
+        await WideEventMiddleware(app)({"type": "http", "method": "GET", "path": "/health", "headers": []}, None, send)
+    events = [json.loads(r.message) if False else r for r in caplog.records if r.name == "wingman.wide_event"]
+    assert len(events) == 1 and events[0].event_type == "http_request" and events[0].status_code == 200

docs/logging.md

@@ -0,0 +1,53 @@
+# Structured logging baseline (Wingman #7)
+
+## Schema
+
+All services emit one JSON object per line to **stdout** via
+`backend/app/logging_config.py` (`JsonFormatter`, `configure_logging`).
+
+| Field | Notes |
+|---|---|
+| `timestamp`, `level`, `logger`, `message` | ISO-8601 UTC, stdlib level, module name |
+| `service_name`, `service_version`, `environment` | `wingman-backend`/`wingman-bot`, `APP_VERSION`, `ENVIRONMENT` |
+| `event_type` | `log` (default), `http_request` (wide event) |
+| `request_id`, `trace_id` | Inbound `x-request-id` or generated UUID; same value until tracing is adopted |
+| Wide event only | `request_method`, `request_path`, `route`, `status_code`, `duration_ms`, `sample_reason` (`ERROR`/`SLOW`/`RANDOM`) |
+| Errors only | `error_class`, `error_message` (redacted, truncated), `error_stack_hash` (hash, never full stack) |
+
+Extra `extra={...}` fields are included unless the normalised field name
+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.
+
+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.
+
+## Destinations and retention — current state
+
+| Destination | Status | Retention |
+|---|---|---|
+| Container stdout (`compose.yaml`: backend, bot) | **Actual today** — collected only if the host captures it | Docker default json-file driver, no rotation configured in this repo |
+| 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 |
+
+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
+`docker logs` output sampled at incident time.
+
+## Controls / configuration
+
+`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.
+
+## Needed for stronger assessment evidence
+
+1. Deploy a log shipper/sink and configure rotation; record the real retention period.
+2. Add OpenTelemetry tracing so `trace_id`/`span_id` are distinct from `request_id`.
+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.