485 lines
15 KiB
Python
485 lines
15 KiB
Python
"""结构化 JSON 日志 (T9.3).
|
|
|
|
职责:
|
|
- ``JsonLogFormatter`` : 把 ``LogRecord`` 编码成单行 JSON (含 ctx / exc)
|
|
- ``log_event(...)`` : 业务代码一行写结构化事件, 自动走 ctx 字段
|
|
- ``bind_request_context`` : per-request 上下文, 通过 ``contextvars`` 跨异步安全传递
|
|
- ``configure_logging`` : 在 CLI 入口 / 测试夹具里安装 formatter
|
|
|
|
设计要点 (详见 docs/plans/T9-error-handling.md §4):
|
|
- 零第三方依赖, 仅 stdlib ``logging`` + ``contextvars`` + ``json``
|
|
- 不破坏既有 ``logger.info("msg %s", x)`` 形态, 但鼓励 ``log_event`` 走结构化
|
|
- 单元测试可直接读 ``LogRecord``, 不依赖 formatter 编码
|
|
|
|
schema (顶层)::
|
|
|
|
{
|
|
"ts": "2026-06-12T16:30:01.234Z", # ISO-8601 UTC with ms
|
|
"level": "warning",
|
|
"logger": "admin.errors",
|
|
"msg": "...", # 渲染后的文本
|
|
"ctx": {...}, # 结构化字段 (per-request 上下文 + log_event fields)
|
|
"exc": {"type":..., "message":..., "traceback":...} # 异常时才有
|
|
}
|
|
"""
|
|
|
|
from __future__ import annotations
|
|
|
|
import json
|
|
import logging
|
|
import os
|
|
import sys
|
|
import threading
|
|
from contextvars import ContextVar, Token
|
|
from datetime import datetime, timezone
|
|
from typing import Any, Dict, Optional
|
|
|
|
# ---------------- per-request 上下文 (ContextVar) ----------------
|
|
#
|
|
# 异步安全: contextvars 在 asyncio 任务切换时自动跟随, 不同请求之间不会污染.
|
|
# 同步代码同样工作 (Python 3.7+).
|
|
|
|
_request_ctx: ContextVar[Dict[str, Any]] = ContextVar("admin_request_ctx", default={})
|
|
|
|
|
|
def bind_request_context(**fields: Any) -> Token[Dict[str, Any]]:
|
|
"""写入 per-request 上下文, 返回 token 用于 ``clear_request_context``.
|
|
|
|
用法 (FastAPI middleware)::
|
|
|
|
@app.middleware("http")
|
|
async def ctx_middleware(request, call_next):
|
|
token = bind_request_context(
|
|
request_id=generate_request_id(),
|
|
path=request.url.path,
|
|
method=request.method,
|
|
)
|
|
try:
|
|
return await call_next(request)
|
|
finally:
|
|
clear_request_context(token)
|
|
"""
|
|
base = dict(_request_ctx.get())
|
|
base.update(fields)
|
|
return _request_ctx.set(base)
|
|
|
|
|
|
def clear_request_context(token: Token[Dict[str, Any]]) -> None:
|
|
"""释放 ``bind_request_context`` 写入的上下文."""
|
|
_request_ctx.reset(token)
|
|
|
|
|
|
def current_context() -> Dict[str, Any]:
|
|
"""读取当前 per-request 上下文的快照 (拷贝)."""
|
|
return dict(_request_ctx.get())
|
|
|
|
|
|
# ---------------- JsonLogFormatter ----------------
|
|
|
|
|
|
# LogRecord 默认有 20+ 属性, 不应直接整对象 dict().
|
|
# 安全白名单: 只有这些键允许作为 ctx 字段透传.
|
|
_CTX_SAFE_KEYS = frozenset(
|
|
{
|
|
"code",
|
|
"path",
|
|
"method",
|
|
"request_id",
|
|
"user_id",
|
|
"status",
|
|
"event",
|
|
"duration_ms",
|
|
"code_count",
|
|
"http_status",
|
|
"fields",
|
|
"function",
|
|
}
|
|
)
|
|
|
|
|
|
# 单条日志最大体积, 超过截断 (防 traceback 巨大撑爆日志).
|
|
_MAX_TRACEBACK_CHARS = 4096
|
|
_MAX_LOG_BYTES = 8 * 1024
|
|
|
|
|
|
class JsonLogFormatter(logging.Formatter):
|
|
"""把 ``LogRecord`` 编码为单行 JSON 字符串.
|
|
|
|
字段顺序 (稳定)::
|
|
|
|
ts, level, logger, msg, ctx, exc?
|
|
|
|
设计权衡:
|
|
- ``msg`` 字段保留渲染后的纯文本, 兼容 ``grep`` / 旧日志栈.
|
|
- ``ctx`` 字段把结构化字段从 ``LogRecord.__dict__`` / ``extra`` 抽出来,
|
|
排障时可以 ``jq '.ctx.code'`` 直接取值.
|
|
- ``exc`` 仅在 ``record.exc_info`` 存在时输出, 且对 ``traceback`` 长度设上限.
|
|
"""
|
|
|
|
def __init__(self, *, ensure_ascii: bool = False) -> None:
|
|
super().__init__()
|
|
self._ensure_ascii = ensure_ascii
|
|
|
|
def format(self, record: logging.LogRecord) -> str: # noqa: A003 - stdlib API
|
|
payload: Dict[str, Any] = {
|
|
"ts": _format_ts(record.created),
|
|
"level": record.levelname.lower(),
|
|
"logger": record.name,
|
|
"msg": record.getMessage(),
|
|
}
|
|
|
|
ctx = _extract_ctx(record)
|
|
ctx.update(current_context())
|
|
if ctx:
|
|
payload["ctx"] = ctx
|
|
|
|
if record.exc_info:
|
|
payload["exc"] = _format_exc(record)
|
|
|
|
text = json.dumps(payload, ensure_ascii=self._ensure_ascii, default=str)
|
|
if len(text.encode("utf-8")) <= _MAX_LOG_BYTES:
|
|
return text
|
|
|
|
compact = _compact_payload(payload)
|
|
text = json.dumps(compact, ensure_ascii=self._ensure_ascii, default=str)
|
|
if len(text.encode("utf-8")) <= _MAX_LOG_BYTES:
|
|
return text
|
|
|
|
# 仍然过大时，保底只保留基础字段，避免输出非法 JSON。
|
|
fallback = {
|
|
"ts": payload["ts"],
|
|
"level": payload["level"],
|
|
"logger": payload["logger"],
|
|
"msg": _truncate_text(str(payload["msg"]), 512),
|
|
"ctx": {"truncated": True},
|
|
}
|
|
if "exc" in payload:
|
|
fallback["exc"] = {
|
|
"type": payload["exc"].get("type", "Unknown"),
|
|
"message": _truncate_text(str(payload["exc"].get("message", "")), 256),
|
|
"traceback": "...truncated",
|
|
"truncated": True,
|
|
}
|
|
return json.dumps(fallback, ensure_ascii=self._ensure_ascii, default=str)
|
|
|
|
|
|
# ---------------- log_event helper ----------------
|
|
|
|
|
|
# LogRecord.__dict__ 已存在的属性 (LogRecord 自带, 与 extra 冲突时优先 builtin).
|
|
# 避免 ``extra={"name": ...}`` 把 record.name 覆盖掉.
|
|
_RESERVED_LOGRECORD_KEYS = frozenset(
|
|
{
|
|
"name",
|
|
"msg",
|
|
"args",
|
|
"levelname",
|
|
"levelno",
|
|
"pathname",
|
|
"filename",
|
|
"module",
|
|
"exc_info",
|
|
"exc_text",
|
|
"stack_info",
|
|
"lineno",
|
|
"funcName",
|
|
"created",
|
|
"msecs",
|
|
"relativeCreated",
|
|
"thread",
|
|
"threadName",
|
|
"processName",
|
|
"process",
|
|
"asctime",
|
|
"message",
|
|
"taskName",
|
|
}
|
|
)
|
|
|
|
|
|
def log_event(
|
|
logger: logging.Logger,
|
|
level: int,
|
|
event: str,
|
|
*,
|
|
msg: Optional[str] = None,
|
|
**fields: Any,
|
|
) -> None:
|
|
"""写一条结构化事件. ``fields`` 会作为 ``ctx`` 字段进入 JSON 输出.
|
|
|
|
Args:
|
|
logger: 目标 logger
|
|
level: 级别 (e.g. ``logging.WARNING``)
|
|
event: 事件名 (e.g. ``"business_error"``), 进入 ``ctx.event``
|
|
msg: 可选人类可读摘要; 缺省用 ``event``
|
|
**fields: 结构化字段 (e.g. ``code="E01101", path="/api/x"``)
|
|
|
|
行为约束:
|
|
- ``event`` 必填, 防业务代码写散日志
|
|
- ``fields`` 不可覆盖 LogRecord 保留字段 (会抛 ``ValueError``)
|
|
- ``ctx`` 是 dict 字段, 不会与 LogRecord 自带属性冲突
|
|
|
|
注意: 不会自动捕获 ``sys.exc_info()``. 需要记录异常时, 用
|
|
``log_event_exc(logger, level, event, exc_info=sys.exc_info(), ...)``,
|
|
或直接 ``logger.exception(...)`` + ``extra={"ctx": {...}}``.
|
|
"""
|
|
if not event:
|
|
raise ValueError("log_event: 'event' is required")
|
|
|
|
safe_fields: Dict[str, Any] = {}
|
|
for k, v in fields.items():
|
|
if k in _RESERVED_LOGRECORD_KEYS:
|
|
raise ValueError(
|
|
f"log_event: field name {k!r} collides with LogRecord builtin"
|
|
)
|
|
safe_fields[k] = v
|
|
safe_fields.setdefault("event", event)
|
|
|
|
summary = msg if msg is not None else event
|
|
# 强制 ctx 作为独立字段进入 record.__dict__, formatter 提取时优先取它.
|
|
safe_fields["ctx"] = safe_fields.get("ctx", {})
|
|
if not isinstance(safe_fields["ctx"], dict):
|
|
# 业务误传: 强制转 dict, 防 json.dumps 失败.
|
|
safe_fields["ctx"] = {"value": safe_fields["ctx"]}
|
|
|
|
logger.log(level, summary, extra={"ctx": safe_fields})
|
|
|
|
|
|
def log_event_exc(
|
|
logger: logging.Logger,
|
|
level: int,
|
|
event: str,
|
|
exc_info: Any,
|
|
*,
|
|
msg: Optional[str] = None,
|
|
**fields: Any,
|
|
) -> None:
|
|
"""``log_event`` 的异常版本 — 显式传入 ``exc_info`` (如 ``sys.exc_info()``).
|
|
|
|
用法::
|
|
|
|
try:
|
|
...
|
|
except Exception:
|
|
log_event_exc(logger, logging.ERROR, "unhandled_exception",
|
|
exc_info=sys.exc_info(),
|
|
path=request.url.path, method=request.method)
|
|
raise
|
|
"""
|
|
if not event:
|
|
raise ValueError("log_event_exc: 'event' is required")
|
|
safe_fields: Dict[str, Any] = {}
|
|
for k, v in fields.items():
|
|
if k in _RESERVED_LOGRECORD_KEYS:
|
|
raise ValueError(
|
|
f"log_event_exc: field name {k!r} collides with LogRecord builtin"
|
|
)
|
|
safe_fields[k] = v
|
|
safe_fields.setdefault("event", event)
|
|
safe_fields["ctx"] = safe_fields.get("ctx", {})
|
|
if not isinstance(safe_fields["ctx"], dict):
|
|
safe_fields["ctx"] = {"value": safe_fields["ctx"]}
|
|
|
|
summary = msg if msg is not None else event
|
|
logger.log(level, summary, exc_info=exc_info, extra={"ctx": safe_fields})
|
|
|
|
|
|
# ---------------- configure_logging ----------------
|
|
|
|
|
|
# uvicorn 自带 access / error logger, 我们也接管它们, 避免 plain / json 混用.
|
|
_ADMIN_LOGGER_NAMES = (
|
|
"admin",
|
|
"admin.errors",
|
|
"admin.auth",
|
|
"uvicorn",
|
|
"uvicorn.error",
|
|
"uvicorn.access",
|
|
)
|
|
|
|
|
|
_configure_lock = threading.Lock()
|
|
_configured = False
|
|
|
|
|
|
def configure_logging(
|
|
level: str = "INFO",
|
|
fmt: str = "json",
|
|
*,
|
|
stream=None,
|
|
) -> None:
|
|
"""为 ``admin.*`` / uvicorn logger 安装 JSON formatter.
|
|
|
|
Args:
|
|
level: 全局日志级别字符串 (``"DEBUG"`` / ``"INFO"`` / ...). 默认 INFO.
|
|
fmt: ``"json"`` (默认) 或 ``"plain"`` (开发友好).
|
|
stream: 输出流, 默认 ``sys.stderr``.
|
|
|
|
幂等: 多次调用不会重复安装 handler.
|
|
"""
|
|
global _configured
|
|
with _configure_lock:
|
|
if _configured:
|
|
return
|
|
_configured = True
|
|
|
|
if stream is None:
|
|
stream = sys.stderr
|
|
|
|
handler = logging.StreamHandler(stream)
|
|
if fmt == "json":
|
|
handler.setFormatter(JsonLogFormatter())
|
|
else:
|
|
handler.setFormatter(
|
|
logging.Formatter("%(asctime)s %(levelname)s %(name)s: %(message)s")
|
|
)
|
|
|
|
root = logging.getLogger()
|
|
root.setLevel(getattr(logging, level.upper(), logging.INFO))
|
|
# 清空 uvicorn 0.x 默认配置的 handler, 避免重复输出.
|
|
for h in list(root.handlers):
|
|
root.removeHandler(h)
|
|
root.addHandler(handler)
|
|
|
|
# 让 uvicorn 日志走 root, 不再各自打 access log.
|
|
for name in _ADMIN_LOGGER_NAMES:
|
|
lg = logging.getLogger(name)
|
|
lg.handlers.clear()
|
|
lg.propagate = True
|
|
|
|
|
|
def reset_logging_for_tests() -> None:
|
|
"""测试夹具: 解开 ``configure_logging`` 的幂等锁.
|
|
|
|
单元测试中如需多次重新配置, 在 ``teardown`` 调用一次.
|
|
"""
|
|
global _configured
|
|
with _configure_lock:
|
|
_configured = False
|
|
|
|
|
|
def configure_from_env() -> None:
|
|
"""从环境变量安装配置 (``ADMIN_LOG_FORMAT`` / ``ADMIN_LOG_LEVEL``)."""
|
|
fmt = os.environ.get("ADMIN_LOG_FORMAT", "json").lower()
|
|
level = os.environ.get("ADMIN_LOG_LEVEL", "INFO")
|
|
configure_logging(level=level, fmt=fmt)
|
|
|
|
|
|
# ---------------- 内部工具 ----------------
|
|
|
|
|
|
def _format_ts(epoch_seconds: float) -> str:
|
|
"""epoch → ``2026-06-12T16:30:01.234Z``."""
|
|
dt = datetime.fromtimestamp(epoch_seconds, tz=timezone.utc)
|
|
# millisecond 精度, 与 Loki / ELK 默认格式一致.
|
|
return dt.strftime("%Y-%m-%dT%H:%M:%S") + f".{dt.microsecond // 1000:03d}Z"
|
|
|
|
|
|
def _extract_ctx(record: logging.LogRecord) -> Dict[str, Any]:
|
|
"""从 record 抽 ctx 字段.
|
|
|
|
优先级:
|
|
1. ``record.ctx`` (log_event 写入)
|
|
2. ``record.__dict__`` 中白名单键 (兼容 ``logger.info("...", extra={...})``)
|
|
"""
|
|
ctx_obj = getattr(record, "ctx", None)
|
|
if isinstance(ctx_obj, dict):
|
|
return dict(ctx_obj)
|
|
|
|
out: Dict[str, Any] = {}
|
|
for k in _CTX_SAFE_KEYS:
|
|
v = getattr(record, k, None)
|
|
if v is not None:
|
|
out[k] = v
|
|
return out
|
|
|
|
|
|
def _format_exc(record: logging.LogRecord) -> Dict[str, Any]:
|
|
"""序列化异常信息, traceback 超过 4KB 截断."""
|
|
exc_info = record.exc_info
|
|
if not exc_info:
|
|
# 调用方在 ``record.exc_info`` 存在的前提下调用, 这里只是防御.
|
|
return {"type": "Unknown", "message": "", "traceback": ""}
|
|
exc_type, exc_value, _tb = exc_info
|
|
tb_text = ""
|
|
if record.exc_text:
|
|
tb_text = record.exc_text
|
|
else:
|
|
import traceback as _tb_mod
|
|
|
|
tb_text = "".join(_tb_mod.format_exception(exc_type, exc_value, _tb))
|
|
truncated = False
|
|
if len(tb_text) > _MAX_TRACEBACK_CHARS:
|
|
tb_text = tb_text[:_MAX_TRACEBACK_CHARS] + "\n...truncated"
|
|
truncated = True
|
|
payload: Dict[str, Any] = {
|
|
"type": exc_type.__name__ if exc_type else "Unknown",
|
|
"message": str(exc_value) if exc_value is not None else "",
|
|
"traceback": tb_text,
|
|
}
|
|
if truncated:
|
|
payload["truncated"] = True
|
|
return payload
|
|
|
|
|
|
def _compact_payload(payload: Dict[str, Any]) -> Dict[str, Any]:
|
|
"""压缩过大的日志 payload, 保持 JSON 可解析。"""
|
|
compact = dict(payload)
|
|
compact["msg"] = _truncate_text(str(compact.get("msg", "")), 512)
|
|
ctx = compact.get("ctx")
|
|
if isinstance(ctx, dict):
|
|
compact_ctx: Dict[str, Any] = {}
|
|
for key, value in ctx.items():
|
|
compact_ctx[key] = _compact_value(value)
|
|
compact_ctx["truncated"] = True
|
|
compact["ctx"] = compact_ctx
|
|
else:
|
|
compact["ctx"] = {"truncated": True}
|
|
|
|
exc = compact.get("exc")
|
|
if isinstance(exc, dict):
|
|
compact_exc = dict(exc)
|
|
compact_exc["message"] = _truncate_text(
|
|
str(compact_exc.get("message", "")), 256
|
|
)
|
|
compact_exc["traceback"] = _truncate_text(
|
|
str(compact_exc.get("traceback", "")), _MAX_TRACEBACK_CHARS
|
|
)
|
|
compact_exc["truncated"] = True
|
|
compact["exc"] = compact_exc
|
|
|
|
return compact
|
|
|
|
|
|
def _compact_value(value: Any) -> Any:
|
|
if isinstance(value, str):
|
|
return _truncate_text(value, 256)
|
|
if isinstance(value, (int, float, bool)) or value is None:
|
|
return value
|
|
rendered = json.dumps(value, ensure_ascii=False, default=str)
|
|
return _truncate_text(rendered, 256)
|
|
|
|
|
|
def _truncate_text(text: str, limit: int) -> str:
|
|
if len(text) <= limit:
|
|
return text
|
|
if limit <= 12:
|
|
return text[:limit]
|
|
return text[: limit - 12] + "...truncated"
|
|
|
|
|
|
# ---------------- 内部常量 (给测试 / admin.app 复用) ----------------
|
|
|
|
|
|
__all__ = [
|
|
"JsonLogFormatter",
|
|
"bind_request_context",
|
|
"clear_request_context",
|
|
"configure_from_env",
|
|
"configure_logging",
|
|
"current_context",
|
|
"log_event",
|
|
"log_event_exc",
|
|
"reset_logging_for_tests",
|
|
]
|