From 5f7227ded05b80261ac93da8c8dc5b9c7e1a6fd6 Mon Sep 17 00:00:00 2001 From: Johnny Huynh <27847622+johnnyhuy@users.noreply.github.com> Date: Mon, 19 Oct 2026 00:23:38 +1100 Subject: [PATCH 1/2] feat(logging): finalise structured logging baseline Reconcile the preserved baseline with the wide-event controls already on main. Centralise settings-based setup at process entrypoints, document logging conventions and retention gaps, and run logging regression checks in CI. Refs #7 Co-authored-by: OpenAI Codex --- backend/app/logging.py | 21 +++++++ backend/app/main.py | 8 ++- backend/app/slack_bot.py | 3 - backend/run_bot.py | 5 +- backend/tests/test_logging.py | 101 ++++++++++++++++++++++++++++++++++ docs/logging.md | 55 ++++++++++++++++-- mise.toml | 2 +- 7 files changed, 181 insertions(+), 14 deletions(-) create mode 100644 backend/app/logging.py create mode 100644 backend/tests/test_logging.py diff --git a/backend/app/logging.py b/backend/app/logging.py new file mode 100644 index 0000000..0ef7879 --- /dev/null +++ b/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, + ) diff --git a/backend/app/main.py b/backend/app/main.py index 41e22d2..3d3060d 100644 --- a/backend/app/main.py +++ b/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__) diff --git a/backend/app/slack_bot.py b/backend/app/slack_bot.py index a6b19b2..8cde40f 100644 --- a/backend/app/slack_bot.py +++ b/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 diff --git a/backend/run_bot.py b/backend/run_bot.py index aac9b8b..b7083e3 100644 --- a/backend/run_bot.py +++ b/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 diff --git a/backend/tests/test_logging.py b/backend/tests/test_logging.py new file mode 100644 index 0000000..af63780 --- /dev/null +++ b/backend/tests/test_logging.py @@ -0,0 +1,101 @@ +"""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, **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): + 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(): + 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(): + 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 diff --git a/docs/logging.md b/docs/logging.md index cb2a29c..db19f77 100644 --- a/docs/logging.md +++ b/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. diff --git a/mise.toml b/mise.toml index eac01f7..8341999 100644 --- a/mise.toml +++ b/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)" From 44ca0243c47663190d19bdf7795f2d4a36560b38 Mon Sep 17 00:00:00 2001 From: Johnny Huynh <27847622+johnnyhuy@users.noreply.github.com> Date: Mon, 19 Oct 2026 00:25:27 +1100 Subject: [PATCH 2/2] fix(ci): use valid image tags for pull requests Use a stable SHA prefix because the metadata branch placeholder is empty for pull request builds. Add the type hints and docstrings required by the Python contribution guidelines to the logging checks. Co-authored-by: OpenAI Codex --- .github/workflows/build.yml | 2 +- backend/tests/test_logging.py | 12 ++++++++---- 2 files changed, 9 insertions(+), 5 deletions(-) diff --git a/.github/workflows/build.yml b/.github/workflows/build.yml index c9aa501..db690e0 100644 --- a/.github/workflows/build.yml +++ b/.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 diff --git a/backend/tests/test_logging.py b/backend/tests/test_logging.py index af63780..89258b9 100644 --- a/backend/tests/test_logging.py +++ b/backend/tests/test_logging.py @@ -9,7 +9,8 @@ import pytest -def run_logging(code, **settings): +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}, @@ -20,7 +21,8 @@ def run_logging(code, **settings): @pytest.mark.parametrize("service", ["wingman-backend", "wingman-bot"]) -def test_json_stdout_preserves_controls_and_avoids_duplicate_handlers(service): +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 @@ -53,7 +55,8 @@ def test_json_stdout_preserves_controls_and_avoids_duplicate_handlers(service): assert not result.stderr -def test_text_format_and_configured_level(): +def test_text_format_and_configured_level() -> None: + """Honor the selected text format and minimum severity.""" result = run_logging( """ import logging @@ -70,7 +73,8 @@ def test_text_format_and_configured_level(): assert not result.stderr -def test_api_keeps_backend_service_when_importing_bot(): +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