Ewald
57dfbaddb7
- Review and update the master plan against the current state of the repo - Formalize the end of the frontend migration in the master plan - Add new modules and changes to the checklist - Update the target structure and criteria for acceptance - Add new sections for database splitting, handlers separation, and registry/security/observability clarification - Update the summary and operational resume
377 lines
11 KiB
Python
377 lines
11 KiB
Python
"""Runtime observability helpers for aiohttp routes."""
|
|
|
|
from __future__ import annotations
|
|
|
|
import os
|
|
import time
|
|
from typing import Any
|
|
from uuid import uuid4
|
|
|
|
from aiohttp import web
|
|
|
|
from .shared import get_logger, request_id_var
|
|
from .utils import env_float
|
|
|
|
logger = get_logger(__name__)
|
|
|
|
_CLIENT_DISCONNECT_ERRORS = (
|
|
ConnectionResetError,
|
|
BrokenPipeError,
|
|
ConnectionAbortedError,
|
|
OSError,
|
|
)
|
|
_CLIENT_DISCONNECT_ERRNO = frozenset({10053, 10054, 104, 32, 9})
|
|
|
|
MS_PER_S = 1000.0
|
|
_DEFAULT_LOG_RATELIMIT_MS = 2000.0
|
|
_DEFAULT_SLOW_MS = 750.0
|
|
_DEFAULT_RATELIMIT_CLEAN_INTERVAL_MS = 60_000.0
|
|
_DEFAULT_RATELIMIT_CLEAN_WINDOW_MULT = 4.0
|
|
_DEFAULT_RATELIMIT_CLEAN_MIN_CUTOFF_MS = 120_000.0
|
|
|
|
_LOG_RATELIMIT_STATE: dict[str, float] = {}
|
|
_LOG_RATELIMIT_CLEAN_AT = 0.0
|
|
_SENSITIVE_QUERY_KEYS = frozenset(
|
|
{
|
|
"token",
|
|
"api_token",
|
|
"apikey",
|
|
"api_key",
|
|
"authorization",
|
|
"auth",
|
|
"password",
|
|
"secret",
|
|
"key",
|
|
}
|
|
)
|
|
|
|
|
|
def _is_client_disconnect(exc: BaseException) -> bool:
|
|
if isinstance(exc, (ConnectionResetError, BrokenPipeError, ConnectionAbortedError)):
|
|
return True
|
|
if isinstance(exc, OSError):
|
|
errno = getattr(exc, "errno", None)
|
|
if errno in _CLIENT_DISCONNECT_ERRNO:
|
|
return True
|
|
winerror = getattr(exc, "winerror", None)
|
|
if winerror in _CLIENT_DISCONNECT_ERRNO:
|
|
return True
|
|
return False
|
|
|
|
|
|
def _new_request_id() -> str:
|
|
return uuid4().hex
|
|
|
|
|
|
def _get_request_id(request: web.Request) -> str:
|
|
rid = (request.headers.get("X-Request-ID") or "").strip()
|
|
return rid or _new_request_id()
|
|
|
|
|
|
def _env_flag(name: str, default: bool = False) -> bool:
|
|
try:
|
|
raw = os.environ.get(name)
|
|
except Exception:
|
|
raw = None
|
|
if raw is None:
|
|
return default
|
|
value = str(raw).strip().lower()
|
|
return value in ("1", "true", "yes", "on")
|
|
|
|
|
|
def _should_emit_log(key: str, *, window_ms: float) -> bool:
|
|
global _LOG_RATELIMIT_CLEAN_AT
|
|
now = time.monotonic() * MS_PER_S
|
|
try:
|
|
last = _LOG_RATELIMIT_STATE.get(key, 0.0)
|
|
if last and now - last < window_ms:
|
|
return False
|
|
_LOG_RATELIMIT_STATE[key] = now
|
|
|
|
clean_interval_ms = env_float("MJR_OBS_RATELIMIT_CLEAN_INTERVAL_MS", _DEFAULT_RATELIMIT_CLEAN_INTERVAL_MS)
|
|
clean_window_mult = env_float("MJR_OBS_RATELIMIT_CLEAN_WINDOW_MULT", _DEFAULT_RATELIMIT_CLEAN_WINDOW_MULT)
|
|
clean_min_cutoff_ms = env_float("MJR_OBS_RATELIMIT_CLEAN_MIN_CUTOFF_MS", _DEFAULT_RATELIMIT_CLEAN_MIN_CUTOFF_MS)
|
|
|
|
if not _LOG_RATELIMIT_CLEAN_AT or now - _LOG_RATELIMIT_CLEAN_AT > clean_interval_ms:
|
|
cutoff = now - max(window_ms * clean_window_mult, clean_min_cutoff_ms)
|
|
for k, ts in list(_LOG_RATELIMIT_STATE.items()):
|
|
if ts < cutoff:
|
|
_LOG_RATELIMIT_STATE.pop(k, None)
|
|
_LOG_RATELIMIT_CLEAN_AT = now
|
|
except Exception:
|
|
return True
|
|
return True
|
|
|
|
|
|
def _request_path_or_empty(request: web.Request) -> str:
|
|
try:
|
|
return request.path or ""
|
|
except Exception:
|
|
return ""
|
|
|
|
|
|
def _is_majoor_route(path: str) -> bool:
|
|
return path.startswith("/mjr/am/")
|
|
|
|
|
|
def _is_health_poll_path(path: str) -> bool:
|
|
return path in ("/mjr/am/health", "/mjr/am/health/counters")
|
|
|
|
|
|
def _is_error_status(status: int | None) -> bool:
|
|
return status is not None and status >= 400
|
|
|
|
|
|
def _request_header_lower(request: web.Request, header_name: str) -> str:
|
|
try:
|
|
return (request.headers.get(header_name) or "").strip().lower()
|
|
except Exception:
|
|
return ""
|
|
|
|
|
|
def _is_obs_client_opt_out(value: str) -> bool:
|
|
return value in ("0", "false", "off", "disable", "disabled", "no")
|
|
|
|
|
|
def _is_obs_client_opt_in(value: str) -> bool:
|
|
return value in ("1", "true", "on", "enable", "enabled", "yes")
|
|
|
|
|
|
def _client_observability_flags(request: web.Request) -> tuple[str, bool]:
|
|
client_flag = _request_header_lower(request, "X-MJR-OBS")
|
|
return client_flag, _is_obs_client_opt_in(client_flag)
|
|
|
|
|
|
def _should_log(request: web.Request, *, status: int | None, duration_ms: float) -> bool:
|
|
path = _request_path_or_empty(request)
|
|
if not _is_majoor_route(path):
|
|
return False
|
|
client_flag, client_explicit_on = _client_observability_flags(request)
|
|
if _is_obs_client_opt_out(client_flag):
|
|
return False
|
|
if _env_flag("MJR_OBS_LOG_ALL", default=False):
|
|
return True
|
|
if _is_health_poll_path(path):
|
|
return _is_error_status(status)
|
|
if _is_error_status(status):
|
|
return True
|
|
if not _env_flag("MJR_OBS_LOG_SUCCESS", default=False):
|
|
return False
|
|
if not client_explicit_on:
|
|
return False
|
|
if not _env_flag("MJR_OBS_LOG_SLOW", default=False):
|
|
return False
|
|
slow_ms = env_float("MJR_OBS_SLOW_MS", _DEFAULT_SLOW_MS)
|
|
return duration_ms >= slow_ms
|
|
|
|
|
|
@web.middleware
|
|
async def request_context_middleware(request: web.Request, handler):
|
|
if _env_flag("MJR_OBS_DISABLE", default=False):
|
|
return await handler(request)
|
|
|
|
rid = _get_request_id(request)
|
|
request["mjr_request_id"] = rid
|
|
token = _set_request_id_context(rid)
|
|
start = time.perf_counter()
|
|
status: int | None = None
|
|
error: str | None = None
|
|
error_type: str | None = None
|
|
try:
|
|
response = await handler(request)
|
|
status = _response_status_code(response)
|
|
_attach_request_id_header(response, rid)
|
|
return response
|
|
except web.HTTPException as exc:
|
|
status = _http_exception_status_code(exc)
|
|
error_type, error = _exception_error_fields(exc, fallback="HTTPException")
|
|
_attach_request_id_header_to_http_exception(exc, rid)
|
|
raise
|
|
except RuntimeError as exc:
|
|
if "resetting" in str(exc).lower():
|
|
status = 503
|
|
error_type = "DB_RESETTING"
|
|
error = str(exc)
|
|
raise web.HTTPServiceUnavailable(reason="Database is temporarily unavailable") from exc
|
|
status = 500
|
|
error_type, error = _exception_error_fields(exc, fallback="Unhandled error")
|
|
raise
|
|
except Exception as exc:
|
|
status = 500
|
|
error_type, error = _exception_error_fields(exc, fallback="Unhandled error")
|
|
raise
|
|
finally:
|
|
duration_ms = (time.perf_counter() - start) * 1000.0
|
|
request["mjr_duration_ms"] = duration_ms
|
|
_reset_request_id_context(token)
|
|
_emit_request_log(request, status=status, duration_ms=duration_ms, error=error, error_type=error_type)
|
|
|
|
|
|
def _response_status_code(response: Any) -> int:
|
|
try:
|
|
return int(getattr(response, "status", 200) or 200)
|
|
except Exception:
|
|
return 200
|
|
|
|
|
|
def _http_exception_status_code(exc: web.HTTPException) -> int:
|
|
try:
|
|
return int(getattr(exc, "status", 500) or 500)
|
|
except Exception:
|
|
return 500
|
|
|
|
|
|
def _exception_error_fields(exc: Exception, *, fallback: str) -> tuple[str, str]:
|
|
error_type = exc.__class__.__name__
|
|
try:
|
|
return error_type, str(exc)
|
|
except Exception:
|
|
return error_type, fallback
|
|
|
|
|
|
def _attach_request_id_header(response: Any, rid: str) -> None:
|
|
try:
|
|
response.headers["X-Request-ID"] = rid
|
|
except Exception:
|
|
return
|
|
|
|
|
|
def _attach_request_id_header_to_http_exception(exc: web.HTTPException, rid: str) -> None:
|
|
try:
|
|
exc.headers["X-Request-ID"] = rid
|
|
except (AttributeError, TypeError, KeyError) as exc2:
|
|
logger.debug("Unable to attach X-Request-ID to HTTPException: %s", exc2)
|
|
|
|
|
|
def _set_request_id_context(rid: str):
|
|
try:
|
|
if request_id_var is not None:
|
|
return request_id_var.set(rid)
|
|
except Exception:
|
|
return None
|
|
return None
|
|
|
|
|
|
def _reset_request_id_context(token: Any) -> None:
|
|
try:
|
|
if token is not None and request_id_var is not None:
|
|
request_id_var.reset(token)
|
|
except Exception:
|
|
return
|
|
|
|
|
|
def _sanitize_query_params(request: web.Request) -> dict[str, Any]:
|
|
out: dict[str, Any] = {}
|
|
try:
|
|
iterator = request.query.items()
|
|
except Exception:
|
|
return out
|
|
for key, value in iterator:
|
|
k = str(key or "")
|
|
lower = k.lower()
|
|
if lower in _SENSITIVE_QUERY_KEYS or lower.endswith("_token") or lower.endswith("_key"):
|
|
out[k] = "[redacted]"
|
|
continue
|
|
try:
|
|
text = str(value or "")
|
|
except Exception:
|
|
text = ""
|
|
if len(text) > 256:
|
|
text = text[:256] + "..."
|
|
out[k] = text
|
|
return out
|
|
|
|
|
|
def build_request_log_fields(request: web.Request, response_status: int | None = None) -> dict[str, Any]:
|
|
stats = request.get("mjr_stats")
|
|
return {
|
|
"request_id": request.get("mjr_request_id"),
|
|
"method": request.method,
|
|
"path": request.path,
|
|
"query": _sanitize_query_params(request),
|
|
"status": response_status,
|
|
"duration_ms": request.get("mjr_duration_ms"),
|
|
"remote": getattr(request, "remote", None),
|
|
"stats": stats if isinstance(stats, dict) else None,
|
|
}
|
|
|
|
|
|
def _emit_request_log(
|
|
request: web.Request,
|
|
*,
|
|
status: int | None,
|
|
duration_ms: float,
|
|
error: str | None,
|
|
error_type: str | None,
|
|
) -> None:
|
|
try:
|
|
fields = build_request_log_fields(request, response_status=status)
|
|
if error:
|
|
fields["error"] = error
|
|
fields["error_type"] = error_type
|
|
if not _should_log(request, status=status, duration_ms=duration_ms):
|
|
return
|
|
key = _request_log_key(request, status)
|
|
window_ms = env_float("MJR_OBS_RATELIMIT_MS", _DEFAULT_LOG_RATELIMIT_MS)
|
|
if _should_emit_log(key, window_ms=window_ms):
|
|
_emit_request_log_by_status(status, fields)
|
|
except Exception as exc:
|
|
try:
|
|
logger.debug("Observability log emit failed: %s", exc)
|
|
except Exception:
|
|
return
|
|
|
|
|
|
def _request_log_key(request: web.Request, status: int | None) -> str:
|
|
try:
|
|
return f"{request.method}:{request.path}:{status}"
|
|
except Exception:
|
|
return f"unknown:{status}"
|
|
|
|
|
|
def _emit_request_log_by_status(status: int | None, fields: dict[str, Any]) -> None:
|
|
method = fields.get("method") or "?"
|
|
path = fields.get("path") or "?"
|
|
dur = fields.get("duration_ms")
|
|
dur_part = f" ({dur:.0f}ms)" if isinstance(dur, (int, float)) else ""
|
|
msg = f"Request handled | {method} {path} -> {status}{dur_part}"
|
|
if status is not None and status >= 500:
|
|
logger.error(msg, extra=fields)
|
|
elif status is not None and status >= 400:
|
|
logger.warning(msg, extra=fields)
|
|
else:
|
|
logger.info(msg, extra=fields)
|
|
|
|
|
|
__all__ = [
|
|
"_CLIENT_DISCONNECT_ERRORS",
|
|
"_CLIENT_DISCONNECT_ERRNO",
|
|
"_attach_request_id_header",
|
|
"_attach_request_id_header_to_http_exception",
|
|
"_client_observability_flags",
|
|
"_emit_request_log",
|
|
"_emit_request_log_by_status",
|
|
"_env_flag",
|
|
"_exception_error_fields",
|
|
"_get_request_id",
|
|
"_http_exception_status_code",
|
|
"_is_client_disconnect",
|
|
"_is_error_status",
|
|
"_is_health_poll_path",
|
|
"_is_majoor_route",
|
|
"_is_obs_client_opt_in",
|
|
"_is_obs_client_opt_out",
|
|
"_new_request_id",
|
|
"_request_header_lower",
|
|
"_request_log_key",
|
|
"_request_path_or_empty",
|
|
"_reset_request_id_context",
|
|
"_response_status_code",
|
|
"_sanitize_query_params",
|
|
"_set_request_id_context",
|
|
"_should_emit_log",
|
|
"_should_log",
|
|
"build_request_log_fields",
|
|
"request_context_middleware",
|
|
]
|