gabriel / musehub public
test_logging_alerting_section74.py python
498 lines 21.8 KB
Raw
sha256:a10adeeb7a0169cb9900f9806ed7a973047258abb6283724fe55e8eb68ff3f0a init: musehub initial commit Human 171 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.muse_contracts.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):
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):
66 doc = self._format(self._make_record(level=logging.WARNING))
67 assert doc["level"] == "WARNING"
68
69 def test_has_logger(self):
70 doc = self._format(self._make_record())
71 assert doc["logger"] == "musehub.test"
72
73 def test_has_message(self):
74 doc = self._format(self._make_record("hello world"))
75 assert doc["message"] == "hello world"
76
77 def test_has_request_id(self):
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):
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):
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):
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):
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):
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):
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):
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):
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):
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):
175 result = self._apply("password: mysecret")
176 assert "mysecret" not in result
177 assert "***" in result
178
179 def test_token_scrubbed(self):
180 result = self._apply("token=abc123def456ghi")
181 assert "abc123def456ghi" not in result
182 assert "***" in result
183
184 def test_secret_scrubbed(self):
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):
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):
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):
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):
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):
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):
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):
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 @pytest.mark.anyio
257 async def test_request_id_injected_into_response_header(self, client: AsyncClient):
258 resp = await client.get("/healthz")
259 assert "x-request-id" in resp.headers, (
260 "X-Request-Id header missing — cannot correlate client errors with log entries"
261 )
262
263 @pytest.mark.anyio
264 async def test_request_id_is_uuid(self, client: AsyncClient):
265 resp = await client.get("/healthz")
266 rid = resp.headers.get("x-request-id", "")
267 # UUID4 format: xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx
268 assert re.match(
269 r"^[0-9a-f]{8}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{12}$",
270 rid,
271 ), f"X-Request-Id is not a UUID4: {rid!r}"
272
273 @pytest.mark.anyio
274 async def test_different_requests_get_different_ids(self, client: AsyncClient):
275 r1 = await client.get("/healthz")
276 r2 = await client.get("/healthz")
277 assert r1.headers["x-request-id"] != r2.headers["x-request-id"]
278
279 @pytest.mark.anyio
280 async def test_healthz_logged_at_debug(self, client: AsyncClient):
281 """Verify /healthz access records are emitted at DEBUG (not INFO)."""
282 from musehub.middleware.access_log import AccessLogMiddleware
283 import musehub.middleware.access_log as al_mod
284
285 log_calls: list[tuple] = []
286 original_log = al_mod.logger.log
287
288 def capture_log(level: int, *args, **kwargs):
289 log_calls.append((level,) + args)
290 return original_log(level, *args, **kwargs)
291
292 with patch.object(al_mod.logger, "log", side_effect=capture_log):
293 await client.get("/healthz")
294
295 healthz_calls = [c for c in log_calls if c[0] == logging.DEBUG and "/healthz" in str(c)]
296 assert healthz_calls, "/healthz request was not logged at DEBUG"
297
298 @pytest.mark.anyio
299 async def test_non_healthz_logged_at_info(self, client: AsyncClient):
300 """Verify normal routes are logged at INFO."""
301 import musehub.middleware.access_log as al_mod
302
303 log_calls: list[tuple] = []
304 original_log = al_mod.logger.log
305
306 def capture_log(level: int, *args, **kwargs):
307 log_calls.append((level,) + args)
308 return original_log(level, *args, **kwargs)
309
310 with patch.object(al_mod.logger, "log", side_effect=capture_log):
311 await client.get("/healthz") # one call to prime, then
312 await client.get("/api/v1/repos")
313
314 info_calls = [c for c in log_calls if c[0] == logging.INFO and "/api/v1/repos" in str(c)]
315 assert info_calls, "/api/v1/repos was not logged at INFO"
316
317 def test_msign_handle_extracted_no_raw_token_logged(self):
318 """MSign Authorization header: only the handle is extracted, never the raw token."""
319 src = _ACCESS_LOG_MW.read_text()
320 # The middleware must use _MSIGN_HANDLE_RE to extract the handle.
321 assert "_MSIGN_HANDLE_RE" in src or "MSIGN_HANDLE" in src, (
322 "AccessLogMiddleware does not extract the MSign handle"
323 )
324 # The raw authorization value must NOT be logged.
325 assert "auth_header" not in src.split("user_id")[1].split("logger.log")[0] if "logger.log" in src else True, (
326 "Raw Authorization value may be logged"
327 )
328
329 def test_raw_authorization_not_in_log_call(self):
330 """The raw auth header value must never be passed to logger.log."""
331 src = _ACCESS_LOG_MW.read_text()
332 # logger.log call must not reference auth_header or raw_val
333 log_section = src[src.find("logger.log"):]
334 assert "auth_header" not in log_section, (
335 "auth_header (raw token value) passed to logger.log"
336 )
337
338
339 # ═══════════════════════════════════════════════════════════════════════════════
340 # main.py wiring
341 # ═══════════════════════════════════════════════════════════════════════════════
342
343 class TestMainPyLoggingWiring:
344 _src = _MAIN_PY.read_text()
345
346 def test_configure_logging_used_not_basicconfig(self):
347 """main.py must call configure_logging(), not logging.basicConfig()."""
348 assert "configure_logging" in self._src, (
349 "main.py does not call configure_logging() from musehub.logging_config"
350 )
351 # basicConfig must be gone
352 assert "logging.basicConfig" not in self._src, (
353 "main.py still calls logging.basicConfig — replace with configure_logging()"
354 )
355
356 def test_access_log_middleware_imported(self):
357 assert "AccessLogMiddleware" in self._src, (
358 "AccessLogMiddleware not imported in main.py"
359 )
360
361 def test_access_log_middleware_added(self):
362 assert "add_middleware(AccessLogMiddleware)" in self._src, (
363 "AccessLogMiddleware not registered with app.add_middleware()"
364 )
365
366 def test_access_log_middleware_is_outermost(self):
367 """AccessLogMiddleware must be added AFTER CORSMiddleware (= outermost layer)."""
368 cors_pos = self._src.find("add_middleware(\n CORSMiddleware")
369 if cors_pos == -1:
370 cors_pos = self._src.find("add_middleware(CORSMiddleware")
371 access_pos = self._src.find("add_middleware(AccessLogMiddleware)")
372 assert cors_pos != -1, "CORSMiddleware not found in main.py"
373 assert access_pos != -1, "AccessLogMiddleware not found in main.py"
374 assert access_pos > cors_pos, (
375 "AccessLogMiddleware is not outermost — it must be add_middleware'd AFTER CORSMiddleware"
376 )
377
378
379 # ═══════════════════════════════════════════════════════════════════════════════
380 # CloudWatch alerts script
381 # ═══════════════════════════════════════════════════════════════════════════════
382
383 class TestCloudWatchAlertsScript:
384 _src = _CW_SCRIPT.read_text()
385
386 def test_script_exists(self):
387 assert _CW_SCRIPT.exists(), "deploy/cloudwatch-alerts.sh not found"
388
389 def test_log_group_defined(self):
390 assert "/musehub/app" in self._src, (
391 "CloudWatch log group /musehub/app not defined in cloudwatch-alerts.sh"
392 )
393
394 def test_30_day_hot_retention(self):
395 assert "30" in self._src and "retention" in self._src.lower(), (
396 "30-day hot retention not set in cloudwatch-alerts.sh"
397 )
398 # The actual AWS CLI call
399 assert "put-retention-policy" in self._src, (
400 "aws logs put-retention-policy not called in cloudwatch-alerts.sh"
401 )
402 assert "retention-in-days" in self._src
403
404 def test_5xx_alarm_threshold_1_percent(self):
405 assert 'THRESHOLD_5XX_RATE="1"' in self._src or "THRESHOLD_5XX_RATE=1" in self._src, (
406 "5xx rate alarm threshold must be 1% — change THRESHOLD_5XX_RATE"
407 )
408
409 def test_5xx_metric_filter_defined(self):
410 assert "5xx" in self._src.lower() and "put-metric-filter" in self._src, (
411 "No metric filter for 5xx responses in cloudwatch-alerts.sh"
412 )
413
414 def test_p99_latency_alarm_threshold_2000ms(self):
415 assert 'THRESHOLD_P99_LATENCY_MS="2000"' in self._src or "2000" in self._src, (
416 "p99 latency alarm threshold must be 2000ms"
417 )
418 assert "p99" in self._src.lower() or "P99" in self._src, (
419 "p99 statistic not used for latency alarm"
420 )
421
422 def test_duration_metric_filter_defined(self):
423 assert "duration_ms" in self._src or "RequestDuration" in self._src, (
424 "No metric filter for request duration in cloudwatch-alerts.sh"
425 )
426
427 def test_disk_alarm_threshold_80_percent(self):
428 assert 'THRESHOLD_DISK_PCT="80"' in self._src or "THRESHOLD_DISK_PCT=80" in self._src, (
429 "Disk alarm threshold must be 80%"
430 )
431 assert "disk" in self._src.lower(), (
432 "No disk alarm in cloudwatch-alerts.sh"
433 )
434
435 def test_db_connections_alarm_threshold_90_percent(self):
436 assert 'THRESHOLD_DB_CONN_PCT="90"' in self._src or "THRESHOLD_DB_CONN_PCT=90" in self._src, (
437 "DB connections alarm threshold must be 90%"
438 )
439 assert "DatabaseConnections" in self._src or "db_connections" in self._src.lower(), (
440 "No DB connections alarm in cloudwatch-alerts.sh"
441 )
442
443 def test_sns_topic_created(self):
444 assert "sns create-topic" in self._src, (
445 "SNS topic not created in cloudwatch-alerts.sh"
446 )
447
448 def test_sns_sms_subscription(self):
449 assert "protocol sms" in self._src or "--protocol sms" in self._src, (
450 "No SMS subscription in cloudwatch-alerts.sh"
451 )
452
453 def test_sns_email_subscription(self):
454 assert "protocol email" in self._src or "--protocol email" in self._src, (
455 "No email subscription in cloudwatch-alerts.sh"
456 )
457
458 def test_alarm_actions_use_sns(self):
459 assert "alarm-actions" in self._src and "SNS_ARN" in self._src, (
460 "CloudWatch alarms must route to the SNS topic"
461 )
462
463
464 # ═══════════════════════════════════════════════════════════════════════════════
465 # On-call runbook
466 # ═══════════════════════════════════════════════════════════════════════════════
467
468 class TestOnCallRunbook:
469 _src = _ON_CALL_DOC.read_text()
470
471 def test_runbook_exists(self):
472 assert _ON_CALL_DOC.exists(), "docs/on-call-runbook.md not found"
473
474 def test_references_gabriel(self):
475 assert "gabriel" in self._src.lower(), (
476 "On-call runbook does not name gabriel as the on-call contact"
477 )
478
479 def test_references_sms_or_phone(self):
480 assert "sms" in self._src.lower() or "phone" in self._src.lower(), (
481 "On-call runbook does not mention SMS / phone alerting"
482 )
483
484 def test_references_cloudwatch_log_group(self):
485 assert "/musehub/app" in self._src, (
486 "On-call runbook does not reference CloudWatch log group /musehub/app"
487 )
488
489 def test_documents_cold_log_retention(self):
490 assert "365" in self._src or "1-year" in self._src or "one year" in self._src.lower(), (
491 "On-call runbook does not document 1-year cold log retention"
492 )
493
494 def test_all_four_alarms_documented(self):
495 for alarm in ("5xx", "p99", "disk", "connections"):
496 assert alarm.lower() in self._src.lower(), (
497 f"On-call runbook does not document the '{alarm}' alarm"
498 )
File History 1 commit
sha256:a10adeeb7a0169cb9900f9806ed7a973047258abb6283724fe55e8eb68ff3f0a init: musehub initial commit Human 171 days ago