Files
hair/gateway/logging_middleware.py
T
UbuntuandClaude bb9f55e93c feat(gateway): 全局串行化(并发=1) + 记录入参/出参/耗时日志
并发模型从「每worker并发1 + 多worker并行」改为全局串行:同一时间
只处理1个请求,其余排队;多 worker 仅作热备(主 worker 坏了才用备机)。
接口4(face/features) 走豆包、不占 GPU,不纳入串行。

- pool: asyncio.Semaphore(max_global_concurrency=1) + acquire/release_global_slot
  (依赖单进程 uvicorn 部署,已在注释中标注)
- forward: proxy_request 最外层 acquire 全局槽、try/finally 全路径释放;
  入参 multipart 解析挂 request.state;原重试/故障转移逻辑抽到 _dispatch_with_retries
- reqlog(新): 标量入参保留;图片(file/base64)存盘转URL,绝不内嵌base64;
  出参递归摘要截断(landmarks/长串/大数组)
- logging_middleware: RequestLogEntry 加 request_params/response_data,
  jsonl 全量记录;_load_from_logfile 同步映射防重启丢字段;get_stats recent 暴露
- /gateway-health 暴露 global_max/global_busy/global_waiting
- config: dispatch 新增 max_global_concurrency / max_queue_wait_seconds
- tests: test_reqlog + test_gateway_serialization(9 用例)

顺带提交此前未提交的网关统计(daily stats 接口)与耗时看板(api_timing_dashboard.html)。

Co-Authored-By: Claude <noreply@anthropic.com>
2026-07-23 22:56:48 +08:00

669 lines
24 KiB
Python
Raw Blame History

This file contains ambiguous Unicode characters
This file contains Unicode characters that might be confused with other characters. If you think that this is intentional, you can safely ignore this warning. Use the Escape button to reveal them.
"""请求日志中间件:为每个请求记录时间、路径、耗时等,并提供统计查询。
- 内存环形缓冲区(最近 N 条)
- JSON Lines 文件持久化(自动轮转)
- ASGI 中间件透明捕获请求/响应
"""
import datetime
import json
import logging
import time
from collections import deque
from dataclasses import asdict, dataclass, field
from pathlib import Path
from typing import Any, Dict, List, Optional
from gateway.reqlog import summarize_for_log
logger = logging.getLogger("gateway.logging_middleware")
# ---------------------------------------------------------------------------
# 数据结构
# ---------------------------------------------------------------------------
@dataclass
class RequestLogEntry:
"""单条请求日志。"""
timestamp: str # ISO-8601
method: str
path: str
status_code: int
duration_ms: float
client_ip: str
worker: str = "" # 处理请求的 worker URL(空串表示网关本地处理)
response_code: Optional[int] = None # 响应 JSON 中的 code 字段
request_id: Optional[str] = None # 响应 JSON 中的 request_id
request_params: Optional[dict] = None # 入参(图片用 URL 引用,无 base64)
response_data: Optional[Any] = None # 出参摘要(递归截断)
# ---------------------------------------------------------------------------
# 环形缓冲区
# ---------------------------------------------------------------------------
class RingBuffer:
"""固定大小的环形缓冲区,线程安全。"""
def __init__(self, maxlen: int = 2000):
self._deque: deque = deque(maxlen=maxlen)
def append(self, entry: RequestLogEntry) -> None:
self._deque.append(entry)
def snapshot(self) -> List[RequestLogEntry]:
"""返回当前缓冲区副本(最新在前)。"""
return list(reversed(self._deque))
def __len__(self) -> int:
return len(self._deque)
# ---------------------------------------------------------------------------
# JSON Lines 文件写入(含轮转)
# ---------------------------------------------------------------------------
class LogFileWriter:
"""追加写入 JSON Lines 日志文件,自动按行数 / 天数轮转。
轮转策略:保留 1 个备份 (.jsonl.1),不保留更多历史。
"""
def __init__(self, filepath: str, max_lines: int = 10000, max_age_days: int = 7):
self.filepath = Path(filepath)
self.max_lines = max_lines
self.max_age_seconds = max_age_days * 86400
def write(self, entry: RequestLogEntry) -> None:
try:
self._maybe_rotate()
self.filepath.parent.mkdir(parents=True, exist_ok=True)
line = json.dumps(asdict(entry), ensure_ascii=False) + "\n"
with open(self.filepath, "a", encoding="utf-8") as f:
f.write(line)
except Exception:
logger.warning("写入请求日志失败", exc_info=True)
def _maybe_rotate(self) -> None:
if not self.filepath.exists():
return
# 按天数轮转
mtime = self.filepath.stat().st_mtime
if time.time() - mtime > self.max_age_seconds:
self._rotate()
return
# 按行数轮转
try:
with open(self.filepath, "r", encoding="utf-8") as f:
count = sum(1 for _ in f)
if count >= self.max_lines:
self._rotate()
except Exception:
pass # 读不到就算了,下次再说
def _rotate(self) -> None:
backup = self.filepath.with_suffix(".jsonl.1")
if backup.exists():
backup.unlink()
try:
self.filepath.rename(backup)
logger.info("请求日志已轮转: %s%s", self.filepath.name, backup.name)
except Exception:
logger.warning("日志轮转失败", exc_info=True)
# ---------------------------------------------------------------------------
# 模块级全局状态(由 init_logging 初始化)
# ---------------------------------------------------------------------------
_buffer: Optional[RingBuffer] = None
_writer: Optional[LogFileWriter] = None
def init_logging(cfg: dict) -> None:
"""初始化日志缓冲区与文件写入器。"""
global _buffer, _writer
log_cfg = cfg.get("request_log", {})
if not log_cfg.get("enabled", True):
logger.info("请求日志已禁用")
return
log_file = log_cfg.get("log_file", "gateway/request_log.jsonl")
log_path = Path(log_file)
if not log_path.is_absolute():
log_path = Path(__file__).resolve().parent.parent / log_file
_buffer = RingBuffer(maxlen=log_cfg.get("buffer_size", 2000))
_writer = LogFileWriter(
filepath=str(log_path),
max_lines=log_cfg.get("max_file_lines", 10000),
max_age_days=log_cfg.get("max_file_age_days", 7),
)
# 从历史日志文件加载最近 N 条到缓冲区
buffer_size = log_cfg.get("buffer_size", 2000)
loaded = _load_from_logfile(str(log_path), buffer_size)
if loaded > 0:
logger.info("从日志文件恢复 %d 条历史记录", loaded)
logger.info("请求日志已启用 | 缓冲=%d | 文件=%s",
buffer_size, log_path)
def _load_from_logfile(filepath: str, max_entries: int) -> int:
"""从 JSON Lines 日志文件读取最近 max_entries 条到缓冲区。"""
try:
p = Path(filepath)
if not p.exists():
return 0
# 从文件末尾反向读取(高效处理大文件)
with open(p, "rb") as f:
# 估算:每条约 200 bytes,读最后 max_entries * 250 bytes 足够
chunk_size = max_entries * 250
f.seek(0, 2) # 文件末尾
file_size = f.tell()
read_size = min(chunk_size, file_size)
f.seek(max(0, file_size - read_size))
raw = f.read().decode("utf-8", errors="replace")
# 跳过可能不完整的第一行
lines = raw.split("\n")
if file_size > read_size:
# 第一行可能不完整,跳过
lines = lines[1:]
# 去掉末尾空行
lines = [l for l in lines if l.strip()]
# 只取最后 max_entries 条
lines = lines[-max_entries:]
count = 0
for line in lines:
try:
data = json.loads(line)
entry = RequestLogEntry(
timestamp=data.get("timestamp", ""),
method=data.get("method", ""),
path=data.get("path", ""),
status_code=data.get("status_code", 0),
duration_ms=data.get("duration_ms", 0.0),
client_ip=data.get("client_ip", ""),
worker=data.get("worker", ""),
response_code=data.get("response_code"),
request_id=data.get("request_id"),
request_params=data.get("request_params"),
response_data=data.get("response_data"),
)
_buffer.append(entry)
count += 1
except (json.JSONDecodeError, KeyError):
continue
return count
except Exception:
logger.warning("从日志文件恢复历史记录失败", exc_info=True)
return 0
def is_initialized() -> bool:
return _buffer is not None
# ---------------------------------------------------------------------------
# ASGI 中间件
# ---------------------------------------------------------------------------
def _should_log(path: str) -> bool:
"""只记录 API 请求(/api/ 路径),跳过静态文件、健康检查等。"""
return path.startswith("/api/")
async def request_logging_middleware(request, call_next):
"""记录每个请求的耗时、状态码等信息。"""
# 未初始化或不需要记录的路径 → 直接放行
if _buffer is None or not _should_log(request.url.path):
return await call_next(request)
start = time.perf_counter()
# 获取客户端 IP(优先级:X-Forwarded-For > X-Real-IP > client.host
client_ip = request.client.host if request.client else "unknown"
forwarded = request.headers.get("x-forwarded-for")
if forwarded:
client_ip = forwarded.split(",")[0].strip()
else:
real_ip = request.headers.get("x-real-ip")
if real_ip:
client_ip = real_ip.strip()
response = await call_next(request)
duration_ms = round((time.perf_counter() - start) * 1000, 2)
# 读取 worker URL(由 forward.py 在转发时写入 request.state
worker_url = getattr(request.state, "worker_url", None) or ""
# 提取响应 body 并解析业务字段(仅 JSON 响应)
response_code = None
request_id = None
response_data = None
content_type = response.headers.get("content-type", "")
if "application/json" in content_type or "application/json" in (response.media_type or ""):
# 读取 body(兼容 body_iterator 和 body 两种属性)
body = getattr(response, "body", None)
if body is None:
body = b""
async for chunk in response.body_iterator:
body += chunk
try:
data = json.loads(body)
response_code = data.get("code")
request_id = data.get("request_id")
response_data = summarize_for_log(data)
except (json.JSONDecodeError, UnicodeDecodeError):
pass
# 如果读取了 body_iterator,需要重建响应
if not hasattr(response, "body") or response.body is None:
from starlette.responses import Response as StarletteResponse
response = StarletteResponse(
content=body,
status_code=response.status_code,
headers=dict(response.headers),
media_type=response.media_type,
)
# 入参(由 forward.py / 接口4 handler 挂到 request.state
request_params = getattr(request.state, "log_request_params", None)
# 记录
now = datetime.datetime.utcnow()
entry = RequestLogEntry(
timestamp=now.strftime("%Y-%m-%dT%H:%M:%S.") +
f"{now.microsecond // 1000:03d}Z",
method=request.method,
path=request.url.path,
status_code=response.status_code,
duration_ms=duration_ms,
client_ip=client_ip,
worker=worker_url,
response_code=response_code,
request_id=request_id,
request_params=request_params,
response_data=response_data,
)
_buffer.append(entry)
if _writer is not None:
_writer.write(entry)
return response
# ---------------------------------------------------------------------------
# 统计查询
# ---------------------------------------------------------------------------
def get_stats() -> Dict[str, Any]:
"""基于缓冲区数据计算统计摘要,返回给统计页面使用。"""
if _buffer is None:
return {
"summary": {"total": 0, "success_rate": 0, "avg_duration_ms": 0,
"min_duration_ms": 0, "max_duration_ms": 0},
"endpoints": [],
"workers": [],
"recent": [],
"last_updated": datetime.datetime.utcnow().isoformat() + "Z",
}
snapshot = _buffer.snapshot()
total = len(snapshot)
if total == 0:
return {
"summary": {"total": 0, "success_rate": 0, "avg_duration_ms": 0,
"min_duration_ms": 0, "max_duration_ms": 0},
"endpoints": [],
"workers": [],
"recent": [],
"last_updated": datetime.datetime.utcnow().isoformat() + "Z",
}
# 汇总指标
durations = [e.duration_ms for e in snapshot]
ok_count = sum(1 for e in snapshot if e.response_code == 0)
# 按路径聚合
by_path: Dict[str, dict] = {}
for e in snapshot:
path = e.path
if path not in by_path:
by_path[path] = {"count": 0, "total_duration": 0.0, "ok": 0}
by_path[path]["count"] += 1
by_path[path]["total_duration"] += e.duration_ms
if e.response_code == 0:
by_path[path]["ok"] += 1
endpoints = sorted(
({
"path": path,
"count": v["count"],
"avg_duration_ms": round(v["total_duration"] / v["count"], 1),
"max_duration_ms": round(
max(e.duration_ms for e in snapshot if e.path == path), 1),
"success_rate": round(v["ok"] / v["count"] * 100, 1),
} for path, v in by_path.items()),
key=lambda x: -x["count"],
)
# 最近 100 条(最新在前)
recent_100 = snapshot[:100]
recent = [
{
"timestamp": e.timestamp,
"method": e.method,
"path": e.path,
"status_code": e.status_code,
"duration_ms": e.duration_ms,
"client_ip": e.client_ip,
"worker": e.worker,
"response_code": e.response_code,
"request_id": e.request_id,
"request_params": e.request_params,
"response_data": e.response_data,
}
for e in recent_100
]
# 按 worker 聚合
by_worker: Dict[str, dict] = {}
for e in snapshot:
w = e.worker or "(网关本地)"
if w not in by_worker:
by_worker[w] = {"count": 0, "total_duration": 0.0, "ok": 0}
by_worker[w]["count"] += 1
by_worker[w]["total_duration"] += e.duration_ms
if e.response_code == 0:
by_worker[w]["ok"] += 1
workers = sorted(
({
"worker": w,
"count": v["count"],
"avg_duration_ms": round(v["total_duration"] / v["count"], 1),
"success_rate": round(v["ok"] / v["count"] * 100, 1) if v["count"] else 0,
} for w, v in by_worker.items()),
key=lambda x: -x["count"],
)
return {
"summary": {
"total": total,
"success_rate": round(ok_count / total * 100, 1),
"avg_duration_ms": round(sum(durations) / len(durations), 1),
"min_duration_ms": round(min(durations), 1),
"max_duration_ms": round(max(durations), 1),
},
"endpoints": endpoints,
"workers": workers,
"recent": recent,
"last_updated": datetime.datetime.utcnow().isoformat() + "Z",
}
# ---------------------------------------------------------------------------
# 按天统计(读取磁盘日志全量,支持任意历史日期 + 单次换发型耗时拆解)
# ---------------------------------------------------------------------------
# 接口路径 → 编号/名称(对齐 gateway/app.py 里各路由 docstring 中的「接口N」编号)
PATH_INTERFACE_MAP: Dict[str, Dict[str, Any]] = {
"/api/v1/face/measure": {"num": 1, "name": "四庭七眼测量标注"},
"/api/v1/hair/grow": {"num": 2, "name": "C端生发"},
"/api/v1/hair/grow-b": {"num": 3, "name": "B端生发(医生/操作端)"},
"/api/v1/face/features": {"num": 4, "name": "用户特征分析"},
"/api/v1/hairline/generate": {"num": 5, "name": "发际线PNG生成"},
"/api/v1/face/measure-v2": {"num": 6, "name": "四庭七眼测量标注 v2"},
"/api/v1/hair/grow-v2": {"num": 7, "name": "C端生发 v2"},
"/api/v1/head/mask": {"num": 9, "name": "头发遮罩生成"},
"/api/v1/head/band": {"num": 10, "name": "头部外缘膨胀带遮罩"},
}
# 会按「勾选发型数量」串行多次调用 ComfyUI 的接口(耗时 ≈ 固定开销 + 单次换发型耗时 × 发型数)
MULTI_STYLE_PATHS = {
"/api/v1/hair/grow",
"/api/v1/hair/grow-v2",
"/api/v1/hairline/generate",
}
def _log_file_path() -> Path:
"""当前日志文件路径(若尚未 init_logging,用默认路径兜底)。"""
if _writer is not None:
return _writer.filepath
return Path(__file__).resolve().parent.parent / "gateway" / "request_log.jsonl"
def _read_all_log_entries() -> List[dict]:
"""读取磁盘上完整的日志历史(含轮转备份 .jsonl.1,按时间顺序:备份在前)。"""
log_path = _log_file_path()
paths = []
backup = log_path.with_suffix(".jsonl.1")
if backup.exists():
paths.append(backup)
if log_path.exists():
paths.append(log_path)
entries: List[dict] = []
for p in paths:
try:
with open(p, "r", encoding="utf-8") as f:
for line in f:
line = line.strip()
if not line:
continue
try:
entries.append(json.loads(line))
except json.JSONDecodeError:
continue
except Exception:
logger.warning("读取日志文件失败: %s", p, exc_info=True)
return entries
def _parse_ts(ts: str) -> Optional[datetime.datetime]:
for fmt in ("%Y-%m-%dT%H:%M:%S.%fZ", "%Y-%m-%dT%H:%M:%SZ"):
try:
return datetime.datetime.strptime(ts, fmt).replace(tzinfo=datetime.timezone.utc)
except ValueError:
continue
return None
def _percentile(values: List[float], p: float) -> float:
"""线性插值百分位数,values 需已排序。"""
if not values:
return 0.0
if len(values) == 1:
return values[0]
k = (len(values) - 1) * p
f = int(k)
c = min(f + 1, len(values) - 1)
if f == c:
return values[f]
return values[f] + (values[c] - values[f]) * (k - f)
def get_available_dates(tz_offset_hours: float = 8) -> List[str]:
"""返回日志中出现过的所有本地日期(YYYY-MM-DD),最新在前。"""
tz = datetime.timezone(datetime.timedelta(hours=tz_offset_hours))
dates = set()
for e in _read_all_log_entries():
t = _parse_ts(e.get("timestamp", ""))
if t is None:
continue
dates.add(t.astimezone(tz).date().isoformat())
return sorted(dates, reverse=True)
def _estimate_per_style(durations_ms: List[float]) -> Optional[Dict[str, Any]]:
"""从一组请求耗时里拆解出「单次换发型边际耗时」与「固定开销」。
原理:这类接口对每个勾选的发型串行跑一次 ComfyUI,总耗时 ≈ 固定开销(人脸检测等)
+ 单次换发型耗时 × 发型数量。发型数量未被记录,这里用迭代最小二乘估计"量子"
(近似每多选 1 个发型多花多少秒),再据此把样本归类、做线性回归得到最终估计。
样本耗时种类过少(不足以分辨固定开销与边际耗时)时返回 None。
"""
xs = sorted(d / 1000.0 for d in durations_ms if d and d > 0)
if len(xs) < 3:
return None
guess = xs[0]
if guess <= 0:
return None
def _fit(ns: List[int], xs_: List[float]):
n_mean = sum(ns) / len(ns)
x_mean = sum(xs_) / len(xs_)
num = sum((n - n_mean) * (x - x_mean) for n, x in zip(ns, xs_))
den = sum((n - n_mean) ** 2 for n in ns)
if den == 0:
return None
slope = num / den
intercept = x_mean - slope * n_mean
return slope, intercept
for _ in range(8):
ns = [max(1, round(x / guess)) for x in xs]
fit = _fit(ns, xs)
if fit is None or fit[0] <= 0:
break
guess = fit[0]
ns_final = [max(1, round(x / guess)) for x in xs]
if len(set(ns_final)) < 2:
return None # 样本都挤在同一档,无法拆分固定开销 / 边际耗时
fit = _fit(ns_final, xs)
if fit is None or fit[0] <= 0:
return None
slope, intercept = fit
groups: Dict[int, List[float]] = {}
for x, n in zip(xs, ns_final):
groups.setdefault(n, []).append(x)
clusters = [
{"styles": n, "count": len(v), "avg_seconds": round(sum(v) / len(v), 2)}
for n, v in sorted(groups.items())
]
return {
"per_style_seconds": round(slope, 2),
"fixed_overhead_seconds": round(max(intercept, 0.0), 2),
"sample_count": len(xs),
"clusters": clusters,
}
def get_daily_stats(date_str: str, tz_offset_hours: float = 8) -> Dict[str, Any]:
"""统计某一天(本地时区,默认 UTC+8)的接口调用情况。
读取磁盘上的完整日志历史(不受内存环形缓冲区大小限制),返回:
- summary:当天总请求数/成功率/总耗时/平均耗时
- endpoints:按接口分组的详细统计(含接口编号/名称、耗时分布、
对「多发型串行」接口额外给出单次换发型耗时拆解)
- hourly:按小时的请求量分布,供画图用
"""
tz = datetime.timezone(datetime.timedelta(hours=tz_offset_hours))
try:
target_date = datetime.date.fromisoformat(date_str)
except ValueError:
return {"error": f"日期格式错误: {date_str!r},应为 YYYY-MM-DD"}
day_entries = []
for e in _read_all_log_entries():
if not str(e.get("path", "")).startswith("/api/"):
continue
t = _parse_ts(e.get("timestamp", ""))
if t is None:
continue
local = t.astimezone(tz)
if local.date() == target_date:
e = dict(e)
e["_local_hour"] = local.hour
day_entries.append(e)
if not day_entries:
return {
"date": date_str,
"summary": {"total": 0, "success_rate": 0, "avg_duration_ms": 0,
"total_duration_seconds": 0, "min_duration_ms": 0, "max_duration_ms": 0},
"endpoints": [],
"hourly": [],
}
total = len(day_entries)
ok_count = sum(1 for e in day_entries
if e.get("status_code") == 200 and e.get("response_code") in (0, None))
all_durations = sorted(e.get("duration_ms", 0.0) for e in day_entries)
by_path: Dict[str, List[dict]] = {}
for e in day_entries:
by_path.setdefault(e["path"], []).append(e)
endpoints = []
for path, items in by_path.items():
durs = sorted(it.get("duration_ms", 0.0) for it in items)
ok = sum(1 for it in items
if it.get("status_code") == 200 and it.get("response_code") in (0, None))
info = PATH_INTERFACE_MAP.get(path, {"num": None, "name": path})
entry: Dict[str, Any] = {
"path": path,
"interface_num": info["num"],
"interface_name": info["name"],
"count": len(items),
"ok_count": ok,
"fail_count": len(items) - ok,
"success_rate": round(ok / len(items) * 100, 1),
"avg_duration_ms": round(sum(durs) / len(durs), 1),
"median_duration_ms": round(_percentile(durs, 0.5), 1),
"p95_duration_ms": round(_percentile(durs, 0.95), 1),
"min_duration_ms": round(durs[0], 1),
"max_duration_ms": round(durs[-1], 1),
"total_duration_seconds": round(sum(durs) / 1000, 1),
"per_style": None,
}
if path in MULTI_STYLE_PATHS:
entry["per_style"] = _estimate_per_style(durs)
endpoints.append(entry)
endpoints.sort(key=lambda x: -x["count"])
hourly_counts: Dict[int, int] = {}
for e in day_entries:
hourly_counts[e["_local_hour"]] = hourly_counts.get(e["_local_hour"], 0) + 1
hourly = [{"hour": h, "count": hourly_counts.get(h, 0)} for h in range(24) if hourly_counts.get(h, 0) > 0]
return {
"date": date_str,
"summary": {
"total": total,
"success_rate": round(ok_count / total * 100, 1),
"avg_duration_ms": round(sum(all_durations) / total, 1),
"total_duration_seconds": round(sum(all_durations) / 1000, 1),
"min_duration_ms": round(all_durations[0], 1),
"max_duration_ms": round(all_durations[-1], 1),
},
"endpoints": endpoints,
"hourly": hourly,
}