From e534f9b6c45a0c7e8a3a1c3b924b7c9d9938f6be Mon Sep 17 00:00:00 2001 From: Johnny Huynh <27847622+johnnyhuy@users.noreply.github.com> Date: Sun, 18 Oct 2026 23:37:19 +1100 Subject: [PATCH] feat(logging): add structured wide-event logging baseline Co-authored-by: Muse Code --- .env.example | 7 ++ backend/app/config.py | 5 + backend/app/logging_config.py | 137 +++++++++++++++++++++++++++ backend/app/main.py | 6 +- backend/app/slack_bot.py | 4 +- backend/app/vector_store.py | 9 +- backend/run_bot.py | 5 +- backend/tests/test_logging_config.py | 35 +++++++ docs/logging.md | 53 +++++++++++ 9 files changed, 255 insertions(+), 6 deletions(-) create mode 100644 backend/app/logging_config.py create mode 100644 backend/tests/test_logging_config.py create mode 100644 docs/logging.md diff --git a/.env.example b/.env.example index 50f3aa7..9b25004 100644 --- a/.env.example +++ b/.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 diff --git a/backend/app/config.py b/backend/app/config.py index bd7011d..2c62d96 100644 --- a/backend/app/config.py +++ b/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" diff --git a/backend/app/logging_config.py b/backend/app/logging_config.py new file mode 100644 index 0000000..2a6b31a --- /dev/null +++ b/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]) diff --git a/backend/app/main.py b/backend/app/main.py index a7b671a..41e22d2 100644 --- a/backend/app/main.py +++ b/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, diff --git a/backend/app/slack_bot.py b/backend/app/slack_bot.py index 15fe0a8..a6b19b2 100644 --- a/backend/app/slack_bot.py +++ b/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__) diff --git a/backend/app/vector_store.py b/backend/app/vector_store.py index 10c8773..2d3fb20 100644 --- a/backend/app/vector_store.py +++ b/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 diff --git a/backend/run_bot.py b/backend/run_bot.py index 8d8f8e3..aac9b8b 100644 --- a/backend/run_bot.py +++ b/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__": diff --git a/backend/tests/test_logging_config.py b/backend/tests/test_logging_config.py new file mode 100644 index 0000000..130495f --- /dev/null +++ b/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 diff --git a/docs/logging.md b/docs/logging.md new file mode 100644 index 0000000..cb2a29c --- /dev/null +++ b/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.