|
| 1 | +"""Schema regression tests for the structured log output. |
| 2 | +
|
| 3 | +Why these exist: PR #48 unified all webhook handlers onto one |
| 4 | +`msg=webhook_processed` event with a fixed kwarg vocabulary and forbids |
| 5 | +Splunk-reserved field names on the wire. Without these tests the schema |
| 6 | +silently drifts on the next add-a-source / add-a-field PR — which is |
| 7 | +exactly what the unification was supposed to end. |
| 8 | +
|
| 9 | +Two layers are covered: |
| 10 | +
|
| 11 | +1. **Call-site invariants** (per router): capture stdout via `capfd` and |
| 12 | + parse the JSON lines. This is what Splunk actually sees, so it's the |
| 13 | + right thing to assert against. (`structlog.testing.capture_logs` was |
| 14 | + tried first but its global-config swap doesn't reach loggers cached |
| 15 | + under `cache_logger_on_first_use=True`, which silently breaks across |
| 16 | + tests.) |
| 17 | +2. **Processor invariants** (one test class): run the configured processor |
| 18 | + chain on a synthetic event_dict and assert `event→msg`, `level→log_level`, |
| 19 | + reserved-name stripping, and `service/version/env` stamping. |
| 20 | +""" |
| 21 | + |
| 22 | +from __future__ import annotations |
| 23 | + |
| 24 | +import io |
| 25 | +import json |
| 26 | +import logging |
| 27 | +from collections.abc import Iterator |
| 28 | +from pathlib import Path |
| 29 | +from typing import Any, cast |
| 30 | + |
| 31 | +import pytest |
| 32 | +import structlog |
| 33 | +from httpx import AsyncClient |
| 34 | + |
| 35 | +from _keys import CHECKOUT_NOERGLER |
| 36 | +from riptide_collector import __version__ |
| 37 | +from riptide_collector.logging_config import configure_logging |
| 38 | + |
| 39 | +FIXTURES = Path(__file__).parent / "fixtures" |
| 40 | + |
| 41 | + |
| 42 | +def _load(name: str) -> dict[str, Any]: |
| 43 | + return json.loads((FIXTURES / name).read_text()) |
| 44 | + |
| 45 | + |
| 46 | +def _parse_json_lines(stream_text: str) -> list[dict[str, Any]]: |
| 47 | + """Return JSON-object lines from a captured log stream, ignoring |
| 48 | + non-JSON noise (httpx debug lines, etc.).""" |
| 49 | + out: list[dict[str, Any]] = [] |
| 50 | + for raw in stream_text.splitlines(): |
| 51 | + line = raw.strip() |
| 52 | + if not line.startswith("{"): |
| 53 | + continue |
| 54 | + try: |
| 55 | + out.append(json.loads(line)) |
| 56 | + except json.JSONDecodeError: |
| 57 | + continue |
| 58 | + return out |
| 59 | + |
| 60 | + |
| 61 | +def _processed(events: list[dict[str, Any]]) -> list[dict[str, Any]]: |
| 62 | + return [e for e in events if e.get("msg") == "webhook_processed"] |
| 63 | + |
| 64 | + |
| 65 | +@pytest.fixture |
| 66 | +def log_buffer(client: AsyncClient) -> Iterator[io.StringIO]: |
| 67 | + """Swap every root StreamHandler's stream to an in-memory buffer for |
| 68 | + the test. Depends on `client` so it runs AFTER `configure_logging` |
| 69 | + has installed the JSON handler. |
| 70 | +
|
| 71 | + Why not capfd/capsys: the structlog handler captures `sys.stdout` |
| 72 | + at handler-creation time. Once create_app runs in the client fixture, |
| 73 | + that reference is frozen — pytest's later fd/sys redirection doesn't |
| 74 | + reach it. Swapping `handler.stream` directly is the only reliable |
| 75 | + way to test what Splunk would actually see. |
| 76 | + """ |
| 77 | + del client # ordering dependency only |
| 78 | + buf = io.StringIO() |
| 79 | + root = logging.getLogger() |
| 80 | + saved: list[tuple[logging.StreamHandler[Any], Any]] = [] |
| 81 | + for handler in root.handlers: |
| 82 | + if isinstance(handler, logging.StreamHandler): |
| 83 | + saved.append((handler, handler.stream)) |
| 84 | + handler.stream = buf |
| 85 | + try: |
| 86 | + yield buf |
| 87 | + finally: |
| 88 | + for handler, original in saved: |
| 89 | + handler.stream = original |
| 90 | + |
| 91 | + |
| 92 | +@pytest.fixture |
| 93 | +def log_buffer_ignored( |
| 94 | + client_with_ignored_stages: AsyncClient, |
| 95 | +) -> Iterator[io.StringIO]: |
| 96 | + del client_with_ignored_stages |
| 97 | + buf = io.StringIO() |
| 98 | + root = logging.getLogger() |
| 99 | + saved: list[tuple[logging.StreamHandler[Any], Any]] = [] |
| 100 | + for handler in root.handlers: |
| 101 | + if isinstance(handler, logging.StreamHandler): |
| 102 | + saved.append((handler, handler.stream)) |
| 103 | + handler.stream = buf |
| 104 | + try: |
| 105 | + yield buf |
| 106 | + finally: |
| 107 | + for handler, original in saved: |
| 108 | + handler.stream = original |
| 109 | + |
| 110 | + |
| 111 | +# ---------- call-site invariants ---------- |
| 112 | + |
| 113 | + |
| 114 | +class TestWebhookProcessedSchema: |
| 115 | + async def test_pipeline_accepted_then_deduped( |
| 116 | + self, client: AsyncClient, log_buffer: io.StringIO |
| 117 | + ) -> None: |
| 118 | + payload = _load("pipeline_jenkins_completed.json") |
| 119 | + headers = {"Authorization": "Bearer test-checkout-jenkins-bearer"} |
| 120 | + |
| 121 | + r1 = await client.post("/webhooks/pipeline", json=payload, headers=headers) |
| 122 | + r2 = await client.post("/webhooks/pipeline", json=payload, headers=headers) |
| 123 | + |
| 124 | + assert r1.status_code == 202 |
| 125 | + assert r2.status_code == 202 |
| 126 | + events = _processed(_parse_json_lines(log_buffer.getvalue())) |
| 127 | + assert len(events) == 2 |
| 128 | + |
| 129 | + first, second = events |
| 130 | + for ev in events: |
| 131 | + for key in ( |
| 132 | + "msg", |
| 133 | + "log_level", |
| 134 | + "timestamp", |
| 135 | + "service", |
| 136 | + "version", |
| 137 | + "env", |
| 138 | + "webhook_source", |
| 139 | + "outcome", |
| 140 | + "delivery_id", |
| 141 | + "team", |
| 142 | + ): |
| 143 | + assert key in ev, f"missing {key} in {ev}" |
| 144 | + # Splunk-reserved field names must not appear on the wire. |
| 145 | + for forbidden in ("source", "event", "level", "host", "index", "sourcetype"): |
| 146 | + assert forbidden not in ev, f"reserved {forbidden} leaked in {ev}" |
| 147 | + assert ev["webhook_source"] == "pipeline" |
| 148 | + |
| 149 | + assert first["outcome"] == "accepted" |
| 150 | + assert second["outcome"] == "deduped" |
| 151 | + assert first["ci_system"] == "jenkins" |
| 152 | + # Generic field names, not pipeline-namespaced. |
| 153 | + assert "status" in first |
| 154 | + assert "run_id" in first |
| 155 | + |
| 156 | + async def test_argocd_accepted_then_deduped( |
| 157 | + self, client: AsyncClient, log_buffer: io.StringIO |
| 158 | + ) -> None: |
| 159 | + payload = _load("argocd_synced.json") |
| 160 | + headers = {"Authorization": "Bearer test-checkout-argocd-bearer"} |
| 161 | + |
| 162 | + r1 = await client.post("/webhooks/argocd", json=payload, headers=headers) |
| 163 | + r2 = await client.post("/webhooks/argocd", json=payload, headers=headers) |
| 164 | + |
| 165 | + assert r1.status_code == 202 |
| 166 | + assert r2.status_code == 202 |
| 167 | + events = _processed(_parse_json_lines(log_buffer.getvalue())) |
| 168 | + assert len(events) == 2 |
| 169 | + assert events[0]["outcome"] == "accepted" |
| 170 | + assert events[1]["outcome"] == "deduped" |
| 171 | + for ev in events: |
| 172 | + assert ev["webhook_source"] == "argocd" |
| 173 | + assert ev["delivery_id"] |
| 174 | + assert "source" not in ev |
| 175 | + |
| 176 | + async def test_argocd_ignored_carries_delivery_id( |
| 177 | + self, |
| 178 | + client_with_ignored_stages: AsyncClient, |
| 179 | + log_buffer_ignored: io.StringIO, |
| 180 | + ) -> None: |
| 181 | + payload = _load("argocd_synced.json") |
| 182 | + # The canonical fixture targets prod, which the ignored-stages |
| 183 | + # fixture leaves alone. Force a stage the fixture covers. |
| 184 | + payload["destination_namespace"] = "payments-api-syst" |
| 185 | + headers = {"Authorization": "Bearer test-checkout-argocd-bearer"} |
| 186 | + |
| 187 | + r = await client_with_ignored_stages.post("/webhooks/argocd", json=payload, headers=headers) |
| 188 | + |
| 189 | + assert r.status_code == 202 |
| 190 | + events = _processed(_parse_json_lines(log_buffer_ignored.getvalue())) |
| 191 | + assert len(events) == 1 |
| 192 | + ev = events[0] |
| 193 | + assert ev["outcome"] == "ignored" |
| 194 | + assert ev["reason"] == "stage_in_ignored_stages" |
| 195 | + # Regression guard: argocd_event_ignored used to omit delivery_id, |
| 196 | + # leaving triage with no key to grep on. |
| 197 | + assert ev["delivery_id"] |
| 198 | + assert "environment" in ev |
| 199 | + |
| 200 | + async def test_noergler_uses_generic_event_type_field( |
| 201 | + self, client: AsyncClient, log_buffer: io.StringIO |
| 202 | + ) -> None: |
| 203 | + payload = _load("noergler_completed.json") |
| 204 | + headers = {"Authorization": f"Bearer {CHECKOUT_NOERGLER}"} |
| 205 | + |
| 206 | + r = await client.post("/webhooks/noergler", json=payload, headers=headers) |
| 207 | + |
| 208 | + assert r.status_code == 202 |
| 209 | + events = _processed(_parse_json_lines(log_buffer.getvalue())) |
| 210 | + assert len(events) == 1 |
| 211 | + ev = events[0] |
| 212 | + assert ev["webhook_source"] == "noergler" |
| 213 | + # Field is `event_type`, not `noergler_event_type` — webhook_source |
| 214 | + # already disambiguates in Splunk panels. |
| 215 | + assert ev["event_type"] == "completed" |
| 216 | + assert "noergler_event_type" not in ev |
| 217 | + |
| 218 | + |
| 219 | +class TestHttpRequestLog: |
| 220 | + async def test_request_id_header_propagates( |
| 221 | + self, client: AsyncClient, log_buffer: io.StringIO |
| 222 | + ) -> None: |
| 223 | + r = await client.get( |
| 224 | + "/auth/ping", |
| 225 | + headers={ |
| 226 | + "Authorization": "Bearer test-checkout-argocd-bearer", |
| 227 | + "X-Request-Id": "test-rid-abc", |
| 228 | + }, |
| 229 | + ) |
| 230 | + assert r.status_code == 200 |
| 231 | + |
| 232 | + events = _parse_json_lines(log_buffer.getvalue()) |
| 233 | + http = [e for e in events if e.get("msg") == "http_request"] |
| 234 | + assert len(http) == 1 |
| 235 | + ev = http[0] |
| 236 | + assert ev["request_id"] == "test-rid-abc" |
| 237 | + assert ev["path"] == "/auth/ping" |
| 238 | + assert ev["method"] == "GET" |
| 239 | + assert ev["status_code"] == 200 |
| 240 | + assert isinstance(ev["duration_ms"], (int, float)) |
| 241 | + |
| 242 | + async def test_health_path_not_logged( |
| 243 | + self, client: AsyncClient, log_buffer: io.StringIO |
| 244 | + ) -> None: |
| 245 | + for _ in range(3): |
| 246 | + await client.get("/health") |
| 247 | + events = _parse_json_lines(log_buffer.getvalue()) |
| 248 | + assert [e for e in events if e.get("msg") == "http_request"] == [] |
| 249 | + |
| 250 | + |
| 251 | +# ---------- processor-chain invariants ---------- |
| 252 | + |
| 253 | + |
| 254 | +class TestProcessorChain: |
| 255 | + def _run_chain(self, env: str, **kwargs: Any) -> dict[str, Any]: |
| 256 | + configure_logging("INFO", env=env) |
| 257 | + event_dict: dict[str, Any] = {"event": "x", "level": "info", **kwargs} |
| 258 | + processed: Any = event_dict |
| 259 | + from riptide_collector.logging_config import ( |
| 260 | + _make_service_metadata_processor, |
| 261 | + _rename_level, |
| 262 | + _strip_reserved, |
| 263 | + ) |
| 264 | + |
| 265 | + chain = [ |
| 266 | + _make_service_metadata_processor(env), |
| 267 | + structlog.processors.EventRenamer("msg"), |
| 268 | + _rename_level, |
| 269 | + _strip_reserved, |
| 270 | + ] |
| 271 | + for proc in chain: |
| 272 | + processed = proc(cast(Any, None), "info", processed) |
| 273 | + assert isinstance(processed, dict) |
| 274 | + return processed |
| 275 | + |
| 276 | + def test_event_renamed_to_msg_level_to_log_level(self) -> None: |
| 277 | + out = self._run_chain("prod") |
| 278 | + assert out["msg"] == "x" |
| 279 | + assert out["log_level"] == "info" |
| 280 | + assert "event" not in out |
| 281 | + assert "level" not in out |
| 282 | + |
| 283 | + def test_service_metadata_stamped(self) -> None: |
| 284 | + out = self._run_chain("intg") |
| 285 | + assert out["service"] == "riptide-collector" |
| 286 | + assert out["version"] == __version__ |
| 287 | + assert out["env"] == "intg" |
| 288 | + |
| 289 | + def test_splunk_reserved_kwargs_namespaced(self) -> None: |
| 290 | + # Anyone accidentally passing `source=...` or `host=...` as a kwarg |
| 291 | + # would be silently overwritten by Splunk's input metadata. The |
| 292 | + # `_strip_reserved` safety net moves them under `splunk_<name>`. |
| 293 | + out = self._run_chain( |
| 294 | + "prod", |
| 295 | + source="jenkins", |
| 296 | + host="x", |
| 297 | + index="y", |
| 298 | + sourcetype="z", |
| 299 | + ) |
| 300 | + assert out["splunk_source"] == "jenkins" |
| 301 | + assert out["splunk_host"] == "x" |
| 302 | + assert out["splunk_index"] == "y" |
| 303 | + assert out["splunk_sourcetype"] == "z" |
| 304 | + for forbidden in ("source", "host", "index", "sourcetype"): |
| 305 | + assert forbidden not in out |
0 commit comments