gabriel / musehub public

test_logging_alerting.py file-level

at sha256:3 · View file ↗ · Intel ↗

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