gabriel / musehub public
test_logging_alerting.py python
493 lines 22.1 KB
Raw
sha256:bb2baaabdd19320bde50cb69d447fd1c1e571467df729be1a23b5e93064b046a feat(intel): standardize headers, gauge icon, velocity card… Sonnet 4.6 minor ⚠ breaking 144 days ago
1 """Section 7.4 — Logging & alerting tests.
2
3 Covers:
4 Structured JSON logs : JsonFormatter emits timestamp, level, logger, message,
5 request_id, user_id; optional method/path/status/duration_ms.
6 PII scrubbing : PiiFilter redacts Bearer tokens, passwords, secrets from
7 message strings before they reach any handler.
8 Access log middleware: Injects request_id + user_id into contextvars; emits
9 per-request access line; logs /healthz at DEBUG;
10 injects X-Request-Id response header.
11 No PII in access log : Raw Authorization token never logged — only the MSign handle.
12 CloudWatch script : Thresholds match checklist (5xx >1%, p99 >2 s, disk >80%,
13 DB conns >90%); 30-day hot retention; SNS wired up.
14 On-call runbook : docs/on-call-runbook.md exists and references gabriel.
15 main.py wiring : configure_logging used (not basicConfig); AccessLogMiddleware
16 registered.
17 """
18 from __future__ import annotations
19
20 import json
21 import logging
22 import re
23 from pathlib import Path
24 from unittest.mock import AsyncMock, MagicMock, patch
25
26 import pytest
27 from httpx import AsyncClient
28 from musehub.types.json_types import JSONObject
29
30 _ROOT = Path(__file__).resolve().parents[1]
31 _MAIN_PY = _ROOT / "musehub" / "main.py"
32 _LOGGING_CONFIG = _ROOT / "musehub" / "logging_config.py"
33 _ACCESS_LOG_MW = _ROOT / "musehub" / "middleware" / "access_log.py"
34 _CW_SCRIPT = _ROOT / "deploy" / "cloudwatch-alerts.sh"
35 _ON_CALL_DOC = _ROOT / "docs" / "on-call-runbook.md"
36
37
38 # ═══════════════════════════════════════════════════════════════════════════════
39 # JSON formatter
40 # ═══════════════════════════════════════════════════════════════════════════════
41
42 class TestJsonFormatter:
43 def _make_record(self, msg: str = "hello", level: int = logging.INFO) -> logging.LogRecord:
44 record = logging.LogRecord(
45 name="musehub.test",
46 level=level,
47 pathname="test.py",
48 lineno=1,
49 msg=msg,
50 args=(),
51 exc_info=None,
52 )
53 return record
54
55 def _format(self, record: logging.LogRecord) -> JSONObject:
56 from musehub.logging_config import JsonFormatter
57 return json.loads(JsonFormatter().format(record))
58
59 def test_has_timestamp(self) -> None:
60 doc = self._format(self._make_record())
61 assert "timestamp" in doc
62 # ISO-8601 UTC — ends with +00:00
63 assert "+00:00" in doc["timestamp"] or doc["timestamp"].endswith("Z")
64
65 def test_has_level(self) -> None:
66 doc = self._format(self._make_record(level=logging.WARNING))
67 assert doc["level"] == "WARNING"
68
69 def test_has_logger(self) -> None:
70 doc = self._format(self._make_record())
71 assert doc["logger"] == "musehub.test"
72
73 def test_has_message(self) -> None:
74 doc = self._format(self._make_record("hello world"))
75 assert doc["message"] == "hello world"
76
77 def test_has_request_id(self) -> None:
78 from musehub.logging_config import request_id_var
79 token = request_id_var.set("test-req-id-123")
80 try:
81 doc = self._format(self._make_record())
82 assert doc["request_id"] == "test-req-id-123"
83 finally:
84 request_id_var.reset(token)
85
86 def test_has_user_id(self) -> None:
87 from musehub.logging_config import user_id_var
88 token = user_id_var.set("gabriel")
89 try:
90 doc = self._format(self._make_record())
91 assert doc["user_id"] == "gabriel"
92 finally:
93 user_id_var.reset(token)
94
95 def test_request_id_defaults_to_empty_string(self) -> None:
96 from musehub.logging_config import request_id_var
97 # Reset to default.
98 request_id_var.set("")
99 doc = self._format(self._make_record())
100 assert doc["request_id"] == ""
101
102 def test_access_fields_included_when_present(self) -> None:
103 from musehub.logging_config import JsonFormatter
104 record = self._make_record("GET /api/v1 200")
105 record.__dict__.update(
106 method="GET", path="/api/v1", status=200, duration_ms=12.3
107 )
108 doc = json.loads(JsonFormatter().format(record))
109 assert doc["method"] == "GET"
110 assert doc["path"] == "/api/v1"
111 assert doc["status"] == 200
112 assert doc["duration_ms"] == 12.3
113
114 def test_access_fields_absent_when_not_set(self) -> None:
115 doc = self._format(self._make_record())
116 assert "method" not in doc
117 assert "path" not in doc
118 assert "status" not in doc
119 assert "duration_ms" not in doc
120
121 def test_exc_info_included(self) -> None:
122 from musehub.logging_config import JsonFormatter
123 try:
124 raise ValueError("boom")
125 except ValueError:
126 import sys
127 record = logging.LogRecord(
128 name="musehub.test", level=logging.ERROR,
129 pathname="test.py", lineno=1,
130 msg="error", args=(), exc_info=sys.exc_info(),
131 )
132 doc = json.loads(JsonFormatter().format(record))
133 assert "exc_info" in doc
134 assert "ValueError" in doc["exc_info"]
135
136 def test_output_is_valid_json(self) -> None:
137 raw = self._format(self._make_record())
138 assert isinstance(raw, dict) # _format already parses — just check no exception
139
140
141 # ═══════════════════════════════════════════════════════════════════════════════
142 # PII filter
143 # ═══════════════════════════════════════════════════════════════════════════════
144
145 class TestPiiFilter:
146 def _apply(self, msg: str) -> str:
147 from musehub.logging_config import PiiFilter
148 record = logging.LogRecord(
149 name="test", level=logging.INFO,
150 pathname="test.py", lineno=1,
151 msg=msg, args=(), exc_info=None,
152 )
153 f = PiiFilter()
154 f.filter(record)
155 return record.getMessage()
156
157 def test_bearer_token_scrubbed(self) -> None:
158 result = self._apply("Authorization: Bearer eyJhbGciOiJSUzI1NiJ9.payload.sig")
159 assert "eyJhbGciOiJSUzI1NiJ9" not in result
160 assert "Bearer ***" in result
161
162 def test_short_bearer_not_scrubbed(self) -> None:
163 # Strings < 8 chars after Bearer are unlikely to be real tokens.
164 result = self._apply("Bearer short")
165 # No crash — passes through
166 assert result is not None
167
168 def test_password_scrubbed_equals(self) -> None:
169 result = self._apply("password=supersecret123")
170 assert "supersecret123" not in result
171 assert "password=" in result
172 assert "***" in result
173
174 def test_password_scrubbed_colon(self) -> None:
175 result = self._apply("password: mysecret")
176 assert "mysecret" not in result
177 assert "***" in result
178
179 def test_token_scrubbed(self) -> None:
180 result = self._apply("token=abc123def456ghi")
181 assert "abc123def456ghi" not in result
182 assert "***" in result
183
184 def test_secret_scrubbed(self) -> None:
185 result = self._apply("secret=webhook_key_abc123")
186 assert "webhook_key_abc123" not in result
187 assert "***" in result
188
189 def test_normal_message_unchanged(self) -> None:
190 result = self._apply("User gabriel pushed 3 commits to dev")
191 assert result == "User gabriel pushed 3 commits to dev"
192
193 def test_args_expanded_and_scrubbed(self) -> None:
194 from musehub.logging_config import PiiFilter
195 record = logging.LogRecord(
196 name="test", level=logging.INFO,
197 pathname="test.py", lineno=1,
198 msg="auth header: %s",
199 args=("Bearer supersecrettoken123",),
200 exc_info=None,
201 )
202 f = PiiFilter()
203 f.filter(record)
204 result = record.getMessage()
205 assert "supersecrettoken123" not in result
206
207 def test_filter_returns_true(self) -> None:
208 from musehub.logging_config import PiiFilter
209 record = logging.LogRecord(
210 name="test", level=logging.INFO,
211 pathname="test.py", lineno=1, msg="ok", args=(), exc_info=None,
212 )
213 assert PiiFilter().filter(record) is True
214
215
216 # ═══════════════════════════════════════════════════════════════════════════════
217 # configure_logging
218 # ═══════════════════════════════════════════════════════════════════════════════
219
220 class TestConfigureLogging:
221 def test_removes_existing_handlers(self) -> None:
222 from musehub.logging_config import configure_logging, JsonFormatter
223 root = logging.getLogger()
224 # Pre-install a plain handler to simulate basicConfig.
225 root.addHandler(logging.StreamHandler())
226 configure_logging(debug=False)
227 # After configure_logging there should be exactly one handler.
228 assert len(root.handlers) == 1
229 assert isinstance(root.handlers[0].formatter, JsonFormatter)
230
231 def test_debug_sets_debug_level(self) -> None:
232 from musehub.logging_config import configure_logging
233 configure_logging(debug=True)
234 assert logging.getLogger().level == logging.DEBUG
235
236 def test_non_debug_sets_info_level(self) -> None:
237 from musehub.logging_config import configure_logging
238 configure_logging(debug=False)
239 assert logging.getLogger().level == logging.INFO
240
241 def test_handler_has_pii_filter(self) -> None:
242 from musehub.logging_config import configure_logging, PiiFilter
243 configure_logging(debug=False)
244 root = logging.getLogger()
245 filters = [f for h in root.handlers for f in h.filters]
246 assert any(isinstance(f, PiiFilter) for f in filters), (
247 "No PiiFilter found on root logger handlers"
248 )
249
250
251 # ═══════════════════════════════════════════════════════════════════════════════
252 # AccessLogMiddleware
253 # ═══════════════════════════════════════════════════════════════════════════════
254
255 class TestAccessLogMiddleware:
256 async def test_request_id_injected_into_response_header(self, client: AsyncClient) -> None:
257 resp = await client.get("/healthz")
258 assert "x-request-id" in resp.headers, (
259 "X-Request-Id header missing — cannot correlate client errors with log entries"
260 )
261
262 async def test_request_id_is_uuid(self, client: AsyncClient) -> None:
263 resp = await client.get("/healthz")
264 rid = resp.headers.get("x-request-id", "")
265 # UUID4 format: xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx
266 assert re.match(
267 r"^[0-9a-f]{8}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{12}$",
268 rid,
269 ), f"X-Request-Id is not a UUID4: {rid!r}"
270
271 async def test_different_requests_get_different_ids(self, client: AsyncClient) -> None:
272 r1 = await client.get("/healthz")
273 r2 = await client.get("/healthz")
274 assert r1.headers["x-request-id"] != r2.headers["x-request-id"]
275
276 async def test_healthz_logged_at_debug(self, client: AsyncClient) -> None:
277 """Verify /healthz access records are emitted at DEBUG (not INFO)."""
278 from musehub.middleware.access_log import AccessLogMiddleware
279 import musehub.middleware.access_log as al_mod
280
281 log_calls: list[tuple] = []
282 original_log = al_mod.logger.log
283
284 def capture_log(level: int, *args: str, **kwargs: str) -> None:
285 log_calls.append((level,) + args)
286 return original_log(level, *args, **kwargs)
287
288 with patch.object(al_mod.logger, "log", side_effect=capture_log):
289 await client.get("/healthz")
290
291 healthz_calls = [c for c in log_calls if c[0] == logging.DEBUG and "/healthz" in str(c)]
292 assert healthz_calls, "/healthz request was not logged at DEBUG"
293
294 async def test_non_healthz_logged_at_info(self, client: AsyncClient) -> None:
295 """Verify normal routes are logged at INFO."""
296 import musehub.middleware.access_log as al_mod
297
298 log_calls: list[tuple] = []
299 original_log = al_mod.logger.log
300
301 def capture_log(level: int, *args: str, **kwargs: str) -> None:
302 log_calls.append((level,) + args)
303 return original_log(level, *args, **kwargs)
304
305 with patch.object(al_mod.logger, "log", side_effect=capture_log):
306 await client.get("/healthz") # one call to prime, then
307 await client.get("/api/v1/repos")
308
309 info_calls = [c for c in log_calls if c[0] == logging.INFO and "/api/v1/repos" in str(c)]
310 assert info_calls, "/api/v1/repos was not logged at INFO"
311
312 def test_msign_handle_extracted_no_raw_token_logged(self) -> None:
313 """MSign Authorization header: only the handle is extracted, never the raw token."""
314 src = _ACCESS_LOG_MW.read_text()
315 # The middleware must use _MSIGN_HANDLE_RE to extract the handle.
316 assert "_MSIGN_HANDLE_RE" in src or "MSIGN_HANDLE" in src, (
317 "AccessLogMiddleware does not extract the MSign handle"
318 )
319 # The raw authorization value must NOT be logged.
320 assert "auth_header" not in src.split("user_id")[1].split("logger.log")[0] if "logger.log" in src else True, (
321 "Raw Authorization value may be logged"
322 )
323
324 def test_raw_authorization_not_in_log_call(self) -> None:
325 """The raw auth header value must never be passed to logger.log."""
326 src = _ACCESS_LOG_MW.read_text()
327 # logger.log call must not reference auth_header or raw_val
328 log_section = src[src.find("logger.log"):]
329 assert "auth_header" not in log_section, (
330 "auth_header (raw token value) passed to logger.log"
331 )
332
333
334 # ═══════════════════════════════════════════════════════════════════════════════
335 # main.py wiring
336 # ═══════════════════════════════════════════════════════════════════════════════
337
338 class TestMainPyLoggingWiring:
339 _src = _MAIN_PY.read_text()
340
341 def test_configure_logging_used_not_basicconfig(self) -> None:
342 """main.py must call configure_logging(), not logging.basicConfig()."""
343 assert "configure_logging" in self._src, (
344 "main.py does not call configure_logging() from musehub.logging_config"
345 )
346 # basicConfig must be gone
347 assert "logging.basicConfig" not in self._src, (
348 "main.py still calls logging.basicConfig — replace with configure_logging()"
349 )
350
351 def test_access_log_middleware_imported(self) -> None:
352 assert "AccessLogMiddleware" in self._src, (
353 "AccessLogMiddleware not imported in main.py"
354 )
355
356 def test_access_log_middleware_added(self) -> None:
357 assert "add_middleware(AccessLogMiddleware)" in self._src, (
358 "AccessLogMiddleware not registered with app.add_middleware()"
359 )
360
361 def test_access_log_middleware_is_outermost(self) -> None:
362 """AccessLogMiddleware must be added AFTER CORSMiddleware (= outermost layer)."""
363 cors_pos = self._src.find("add_middleware(\n CORSMiddleware")
364 if cors_pos == -1:
365 cors_pos = self._src.find("add_middleware(CORSMiddleware")
366 access_pos = self._src.find("add_middleware(AccessLogMiddleware)")
367 assert cors_pos != -1, "CORSMiddleware not found in main.py"
368 assert access_pos != -1, "AccessLogMiddleware not found in main.py"
369 assert access_pos > cors_pos, (
370 "AccessLogMiddleware is not outermost — it must be add_middleware'd AFTER CORSMiddleware"
371 )
372
373
374 # ═══════════════════════════════════════════════════════════════════════════════
375 # CloudWatch alerts script
376 # ═══════════════════════════════════════════════════════════════════════════════
377
378 class TestCloudWatchAlertsScript:
379 _src = _CW_SCRIPT.read_text()
380
381 def test_script_exists(self) -> None:
382 assert _CW_SCRIPT.exists(), "deploy/cloudwatch-alerts.sh not found"
383
384 def test_log_group_defined(self) -> None:
385 assert "/musehub/app" in self._src, (
386 "CloudWatch log group /musehub/app not defined in cloudwatch-alerts.sh"
387 )
388
389 def test_30_day_hot_retention(self) -> None:
390 assert "30" in self._src and "retention" in self._src.lower(), (
391 "30-day hot retention not set in cloudwatch-alerts.sh"
392 )
393 # The actual AWS CLI call
394 assert "put-retention-policy" in self._src, (
395 "aws logs put-retention-policy not called in cloudwatch-alerts.sh"
396 )
397 assert "retention-in-days" in self._src
398
399 def test_5xx_alarm_threshold_1_percent(self) -> None:
400 assert 'THRESHOLD_5XX_RATE="1"' in self._src or "THRESHOLD_5XX_RATE=1" in self._src, (
401 "5xx rate alarm threshold must be 1% — change THRESHOLD_5XX_RATE"
402 )
403
404 def test_5xx_metric_filter_defined(self) -> None:
405 assert "5xx" in self._src.lower() and "put-metric-filter" in self._src, (
406 "No metric filter for 5xx responses in cloudwatch-alerts.sh"
407 )
408
409 def test_p99_latency_alarm_threshold_2000ms(self) -> None:
410 assert 'THRESHOLD_P99_LATENCY_MS="2000"' in self._src or "2000" in self._src, (
411 "p99 latency alarm threshold must be 2000ms"
412 )
413 assert "p99" in self._src.lower() or "P99" in self._src, (
414 "p99 statistic not used for latency alarm"
415 )
416
417 def test_duration_metric_filter_defined(self) -> None:
418 assert "duration_ms" in self._src or "RequestDuration" in self._src, (
419 "No metric filter for request duration in cloudwatch-alerts.sh"
420 )
421
422 def test_disk_alarm_threshold_80_percent(self) -> None:
423 assert 'THRESHOLD_DISK_PCT="80"' in self._src or "THRESHOLD_DISK_PCT=80" in self._src, (
424 "Disk alarm threshold must be 80%"
425 )
426 assert "disk" in self._src.lower(), (
427 "No disk alarm in cloudwatch-alerts.sh"
428 )
429
430 def test_db_connections_alarm_threshold_90_percent(self) -> None:
431 assert 'THRESHOLD_DB_CONN_PCT="90"' in self._src or "THRESHOLD_DB_CONN_PCT=90" in self._src, (
432 "DB connections alarm threshold must be 90%"
433 )
434 assert "DatabaseConnections" in self._src or "db_connections" in self._src.lower(), (
435 "No DB connections alarm in cloudwatch-alerts.sh"
436 )
437
438 def test_sns_topic_created(self) -> None:
439 assert "sns create-topic" in self._src, (
440 "SNS topic not created in cloudwatch-alerts.sh"
441 )
442
443 def test_sns_sms_subscription(self) -> None:
444 assert "protocol sms" in self._src or "--protocol sms" in self._src, (
445 "No SMS subscription in cloudwatch-alerts.sh"
446 )
447
448 def test_sns_email_subscription(self) -> None:
449 assert "protocol email" in self._src or "--protocol email" in self._src, (
450 "No email subscription in cloudwatch-alerts.sh"
451 )
452
453 def test_alarm_actions_use_sns(self) -> None:
454 assert "alarm-actions" in self._src and "SNS_ARN" in self._src, (
455 "CloudWatch alarms must route to the SNS topic"
456 )
457
458
459 # ═══════════════════════════════════════════════════════════════════════════════
460 # On-call runbook
461 # ═══════════════════════════════════════════════════════════════════════════════
462
463 class TestOnCallRunbook:
464 _src = _ON_CALL_DOC.read_text()
465
466 def test_runbook_exists(self) -> None:
467 assert _ON_CALL_DOC.exists(), "docs/on-call-runbook.md not found"
468
469 def test_references_gabriel(self) -> None:
470 assert "gabriel" in self._src.lower(), (
471 "On-call runbook does not name gabriel as the on-call contact"
472 )
473
474 def test_references_sms_or_phone(self) -> None:
475 assert "sms" in self._src.lower() or "phone" in self._src.lower(), (
476 "On-call runbook does not mention SMS / phone alerting"
477 )
478
479 def test_references_cloudwatch_log_group(self) -> None:
480 assert "/musehub/app" in self._src, (
481 "On-call runbook does not reference CloudWatch log group /musehub/app"
482 )
483
484 def test_documents_cold_log_retention(self) -> None:
485 assert "365" in self._src or "1-year" in self._src or "one year" in self._src.lower(), (
486 "On-call runbook does not document 1-year cold log retention"
487 )
488
489 def test_all_four_alarms_documented(self) -> None:
490 for alarm in ("5xx", "p99", "disk", "connections"):
491 assert alarm.lower() in self._src.lower(), (
492 f"On-call runbook does not document the '{alarm}' alarm"
493 )
File History 1 commit
sha256:bb2baaabdd19320bde50cb69d447fd1c1e571467df729be1a23b5e93064b046a feat(intel): standardize headers, gauge icon, velocity card… Sonnet 4.6 minor ⚠ 144 days ago