优化支付耗时和日志

dev.sh

@@ -18,7 +18,7 @@ BACKEND_HOST="${BACKEND_HOST:-0.0.0.0}"
 BACKEND_PORT="${BACKEND_PORT:-8800}"
 FRONTEND_HOST="${FRONTEND_HOST:-0.0.0.0}"
 FRONTEND_PORT="${FRONTEND_PORT:-5174}"
-LOG_LEVEL="${LOG_LEVEL:-DEBUG}"
+LOG_LEVEL="${LOG_LEVEL:-INFO}"
 MYSQL_IMAGE="${MYSQL_IMAGE:-mysql:8.4}"
 MYSQL_BIND_HOST="${MYSQL_BIND_HOST:-127.0.0.1}"
 MYSQL_HOST_PORT="${MYSQL_HOST_PORT:-3307}"
@@ -40,10 +40,7 @@ DEV_YYB_WORKER_URL="${DEV_YYB_WORKER_URL:-http://127.0.0.1:${YYB_WORKER_PORT}}"
 YYB_WORKER_DATA_DIR="${YYB_WORKER_DATA_DIR:-$ROOT_DIR/data/yyb-worker-dev}"
 YYB_WORKER_NODE_MODULES="$ROOT_DIR/services/yyb-worker/node_modules"
 LOG_DIR="$ROOT_DIR/logs"
-LOG_DATE="$(date +%Y-%m-%d)"
+APP_LOG="$LOG_DIR/app.log"
-BACKEND_LOG="$LOG_DIR/backend-$LOG_DATE.log"
-FRONTEND_LOG="$LOG_DIR/frontend-$LOG_DATE.log"
-WORKER_LOG="$LOG_DIR/yyb-worker-$LOG_DATE.log"
 
 BACKEND_PID=""
 FRONTEND_PID=""
@@ -161,7 +158,7 @@ start_yyb_worker() {
         uv run --project "$ROOT_DIR" python scripts/yyb-worker.py \
             --host 127.0.0.1 \
             --port "$YYB_WORKER_PORT" \
-            --data-dir "$YYB_WORKER_DATA_DIR" 2>&1 | tee -a "$WORKER_LOG"
+            --data-dir "$YYB_WORKER_DATA_DIR"
     ) &
     WORKER_PID=$!
 
@@ -173,7 +170,7 @@ start_yyb_worker() {
         fi
         if [ "$i" = "15" ]; then
             echo "YYB Worker 启动超时，查看日志："
-            tail -n 100 "$WORKER_LOG" 2>/dev/null || true
+            echo "请查看当前终端中的 Worker 输出。"
             exit 1
         fi
         sleep 1
@@ -211,9 +208,8 @@ echo "  前端: http://localhost:${FRONTEND_PORT}"
 echo "  API 代理: ${BACKEND_PROXY_TARGET}"
 echo "  MySQL: ${DB_HOST}:${DB_PORT}/${DB_NAME}"
 echo "  YYB Worker: ${DEV_YYB_WORKER_URL}"
-echo "  后端日志: ${BACKEND_LOG}"
+echo "  应用日志: ${APP_LOG}"
-echo "  前端日志: ${FRONTEND_LOG}"
+echo "  前端与 Worker 输出: 当前终端"
-echo "  Worker 日志: ${WORKER_LOG}"
 echo "  退出: Ctrl+C"
 echo "=============================="
 echo ""
@@ -229,14 +225,14 @@ echo ""
         --reload \
         --reload-dir core \
         --reload-dir utils \
-        --reload-dir web/backend 2>&1 | tee -a "$BACKEND_LOG"
+        --reload-dir web/backend
 ) &
 BACKEND_PID=$!
 
 (
     cd web/frontend
     VITE_BACKEND_TARGET="$BACKEND_PROXY_TARGET" \
-    npm run dev -- --host "$FRONTEND_HOST" --port "$FRONTEND_PORT" 2>&1 | tee -a "$FRONTEND_LOG"
+    npm run dev -- --host "$FRONTEND_HOST" --port "$FRONTEND_PORT"
 ) &
 FRONTEND_PID=$!
 

services/yyb-worker/runtime/scripts/generate-devicefp-jsdom.mjs

@@ -23,7 +23,7 @@ const htmlPath = getArg('--html');
 const goodsUrl = getArg('--goods-url');
 const cookiePath = getArg('--cookies');
 const outputPath = getArg('--output');
-const waitMs = Number.parseInt(getArg('--wait', '12000'), 10);
+const waitMs = Number.parseInt(getArg('--wait', '5000'), 10);
 const useArchivedAssets = argv.includes('--archived-assets');
 
 function fail(message) {
@@ -61,8 +61,18 @@ class GoodsLoader extends ResourceLoader {
 
 const session = cookiePath ? JSON.parse(fs.readFileSync(cookiePath, 'utf8')) : {};
 const cookies = session.cookies || {};
-const captured = [];
 const resourceErrors = [];
+let capturedFp = null;
+let resolveFpCapture = null;
+const startedAt = Date.now();
+
+function captureFp(url, body) {
+  const values = Object.fromEntries(new URLSearchParams(body));
+  if (!values.SessionID || !values.DeviceFP) return;
+  capturedFp = { url, body };
+  if (resolveFpCapture) resolveFpCapture();
+}
+
 const dom = new JSDOM(fs.readFileSync(htmlPath, 'utf8'), {
   url: goodsUrl,
   referrer: 'https://z.iwan.yyb.qq.com/',
@@ -88,7 +98,7 @@ const dom = new JSDOM(fs.readFileSync(htmlPath, 'utf8'), {
       send(body) {
         const requestBody = String(body || '');
         if (this.__yybUrl.includes('fp-behv.fcg')) {
-          captured.push({ url: this.__yybUrl, body: requestBody });
+          captureFp(this.__yybUrl, requestBody);
         }
         this.readyState = 4;
         this.status = 200;
@@ -103,18 +113,23 @@ const dom = new JSDOM(fs.readFileSync(htmlPath, 'utf8'), {
   },
 });
 
-await new Promise(resolve => setTimeout(resolve, Number.isFinite(waitMs) ? waitMs : 12000));
+const timeoutMs = Number.isFinite(waitMs) && waitMs > 0 ? waitMs : 5000;
-const fp = captured.at(-1);
+let timeoutId;
-if (!fp) {
+await Promise.race([
+  new Promise(resolve => {
+    resolveFpCapture = resolve;
+    if (capturedFp) resolve();
+  }),
+  new Promise(resolve => { timeoutId = setTimeout(resolve, timeoutMs); }),
+]);
+clearTimeout(timeoutId);
+if (!capturedFp) {
   dom.window.close();
   fail(`未生成 fp-behv；加载错误: ${resourceErrors.slice(0, 3).join(' | ') || '无'}`);
 }
 
+const fp = capturedFp;
 const values = Object.fromEntries(new URLSearchParams(fp.body));
-if (!values.SessionID || !values.DeviceFP) {
-  dom.window.close();
-  fail('fp-behv 缺少 SessionID 或 DeviceFP');
-}
 const result = {
   generated_at: new Date().toISOString(),
   goods_url: goodsUrl,
@@ -130,3 +145,4 @@ dom.window.close();
 console.log(`DeviceFP 已保存: ${outputPath}`);
 console.log(`SessionID: ${result.session_id}`);
 console.log(`DeviceFP 长度: ${result.device_fp_length}`);
+console.log(`DeviceFP 捕获耗时: ${Date.now() - startedAt}ms`);

services/yyb-worker/runtime/scripts/jsdom-pay.py

@@ -375,7 +375,7 @@ def main() -> int:
     parser.add_argument("--mall-response", default=str(ROOT / "config/mall-order-response.json"))
     parser.add_argument("--out-dir", default=None, help="运行证据目录；默认 config/jsdom-order-<timestamp>")
     parser.add_argument("--qr", default=None, help="付款二维码 PNG 路径")
-    parser.add_argument("--wait", type=int, default=12, help="jsdom 等待 DeviceFP 的秒数")
+    parser.add_argument("--wait", type=int, default=5, help="jsdom 等待 DeviceFP 的秒数")
     parser.add_argument("--zone-id", default="1", help="所选游戏区服 ID")
     parser.add_argument("--pf", default="", help="所选 Android/iOS 支付平台标识")
     parser.add_argument("--amount-fen", type=int, default=0, help="所选点券的价格，单位分（check-only 模式不需要）")

services/yyb-worker/runtime/scripts/yyb-worker.py

@@ -61,8 +61,9 @@ def _safe_log(job: dict, line: str) -> None:
     clean = re.sub(r"(?:token|openid|openkey|cookie)=\S+", "[敏感字段已隐藏]", clean, flags=re.I)
     clean = re.sub(r"(?:pay_token|web_token|anti_token|session_id|sessionid)\s*[:= ]\s*\S+",
                    "[敏感字段已隐藏]", clean, flags=re.I)
+    timestamp = time.strftime("%H:%M:%S")
     with _lock:
-        job["logs"] = (job.get("logs", []) + [clean.strip()])[-100:]
+        job["logs"] = (job.get("logs", []) + [f"[{timestamp}] {clean.strip()}"])[-100:]
 
 
 def _run_process(job_id: str, command: list[str], phase: str, mark_success: bool = True) -> int:
@@ -79,6 +80,8 @@ def _run_process(job_id: str, command: list[str], phase: str, mark_success: bool
     with _lock:
         job["phase"] = phase
         job["status"] = "running"
+    stage_started = time.monotonic()
+    _safe_log(job, f"[{phase}] 开始执行")
     try:
         process = subprocess.Popen(command, cwd=ROOT, stdout=subprocess.PIPE,
                                    stderr=subprocess.STDOUT, text=True,
@@ -89,6 +92,7 @@ def _run_process(job_id: str, command: list[str], phase: str, mark_success: bool
         for line in process.stdout:
             _safe_log(job, line)
         code = process.wait()
+        _safe_log(job, f"[{phase}] 执行结束，耗时 {time.monotonic() - stage_started:.1f} 秒")
         with _lock:
             job["process_pid"] = None
             if code != 0:
@@ -109,6 +113,7 @@ def _run_process(job_id: str, command: list[str], phase: str, mark_success: bool
                 job["message"] = "付款流程已完成"
         return code
     except Exception as exc:  # noqa: BLE001
+        _safe_log(job, f"[{phase}] 执行异常，耗时 {time.monotonic() - stage_started:.1f} 秒")
         with _lock:
             job["status"] = "failed"
             job["message"] = str(exc)
@@ -189,10 +194,13 @@ def _check_payment_once(job_id: str) -> int:
                "--out-dir", str(directory / "jsdom-order")]
     environment = os.environ.copy()
     environment.pop("NODE_OPTIONS", None)
+    check_started = time.monotonic()
+    _safe_log(job, "[到账检测] 开始执行")
     try:
         result = subprocess.run(command, cwd=ROOT, capture_output=True, text=True,
                                 env=environment, timeout=90)
     except subprocess.TimeoutExpired:
+        _safe_log(job, f"[到账检测] 执行超时，耗时 {time.monotonic() - check_started:.1f} 秒")
         with _lock:
             job["payment_last_checked_at"] = int(time.time())
         return 2
@@ -200,6 +208,7 @@ def _check_payment_once(job_id: str) -> int:
         _safe_log(job, line)
     for line in (result.stderr or "").splitlines():
         _safe_log(job, line)
+    _safe_log(job, f"[到账检测] 执行结束，耗时 {time.monotonic() - check_started:.1f} 秒")
     with _lock:
         job["payment_last_checked_at"] = int(time.time())
     return result.returncode

utils/logger.py

@@ -1,33 +1,28 @@
 """日志配置模块"""
 
-import os
 import sys
 import logging
-from datetime import date
+import re
 from logging.handlers import TimedRotatingFileHandler
 from pathlib import Path
 
 from loguru import logger
 
 
-def _should_rotate(message, file):
+class _RelevantAccessFilter(logging.Filter):
-    """自定义轮转条件：每天0点轮转，或单文件超过10M。"""
+    """仅保留异常 HTTP 请求，避免前端轮询淹没业务日志。"""
-    if not file:
+
-        return False
+    _STATUS_RE = re.compile(r'"\s+(\d{3})\b')
-    try:
+
-        # 单文件超过 10M 则轮转
+    def filter(self, record: logging.LogRecord) -> bool:
-        if os.path.getsize(file.name) > 10 * 1024 * 1024:
+        if record.levelno >= logging.WARNING:
             return True
-        # 跨天则轮转：日志日期 ≠ 文件最后修改日期
+        matched = self._STATUS_RE.search(record.getMessage())
-        file_date = date.fromtimestamp(os.path.getmtime(file.name))
+        return bool(matched and int(matched.group(1)) >= 400)
-        log_date = message.record["time"].date()
-        return file_date != log_date
-    except OSError:
-        return False
 
 
-def _configure_standard_logging(level: str, log_dir: Path) -> None:
+def _configure_standard_logging(level: str, log_dir: Path) -> logging.Logger:
-    """将 Uvicorn/FastAPI 的标准日志同步到控制台和文件。"""
+    """将业务日志和关键框架日志收敛到单一轮转文件。"""
     log_level = getattr(logging, level.upper(), logging.INFO)
     formatter = logging.Formatter(
         "%(asctime)s | %(levelname)-8s | %(name)s | %(message)s"
@@ -38,17 +33,30 @@ def _configure_standard_logging(level: str, log_dir: Path) -> None:
     console_handler.setFormatter(formatter)
 
     file_handler = TimedRotatingFileHandler(
-        log_dir / "server.log", when="midnight", backupCount=7, encoding="utf-8"
+        log_dir / "app.log", when="midnight", backupCount=7, encoding="utf-8"
     )
     file_handler.setLevel(log_level)
     file_handler.setFormatter(formatter)
 
-    for name in ("uvicorn", "uvicorn.error", "uvicorn.access", "fastapi", "starlette"):
+    app_logger = logging.getLogger("app")
+    app_logger.handlers.clear()
+    app_logger.handlers = [console_handler, file_handler]
+    app_logger.setLevel(log_level)
+    app_logger.propagate = False
+
+    for name in ("uvicorn", "uvicorn.error", "fastapi", "starlette"):
         standard_logger = logging.getLogger(name)
         standard_logger.handlers = [console_handler, file_handler]
         standard_logger.setLevel(log_level)
         standard_logger.propagate = False
 
+    access_logger = logging.getLogger("uvicorn.access")
+    access_logger.handlers = [console_handler, file_handler]
+    access_logger.filters = [_RelevantAccessFilter()]
+    access_logger.setLevel(logging.INFO)
+    access_logger.propagate = False
+    return app_logger
+
 
 def setup_logger(level: str = "INFO", log_dir: str = None, log_file: str = None) -> None:
     """
@@ -56,45 +64,26 @@ def setup_logger(level: str = "INFO", log_dir: str = None, log_file: str = None)
 
     Args:
         level: 日志级别
-        log_dir: 日志目录路径（文件名按日期自动生成，如 app-2026-06-24.log）
+        log_dir: 日志目录路径（写入 app.log，按日轮转）
         log_file: 日志文件路径（兼容旧接口，优先级低于 log_dir）
     """
-    # 移除默认handler
+    # 移除默认 handler，由标准 logging 统一处理控制台和文件输出。
     logger.remove()
 
-    # 控制台输出
-    logger.add(
-        sys.stdout,
-        level=level,
-        format="<green>{time:YYYY-MM-DD HH:mm:ss}</green> | "
-               "<level>{level: <8}</level> | "
-               "<cyan>{name}</cyan>:<cyan>{function}</cyan>:<cyan>{line}</cyan> | "
-               "<level>{message}</level>",
-        colorize=True,
-    )
-
     # 确定日志文件路径
     if log_dir:
-        # 新接口：按目录 + 日期命名
         dir_path = Path(log_dir)
         dir_path.mkdir(parents=True, exist_ok=True)
-        _configure_standard_logging(level, dir_path)
+        app_logger = _configure_standard_logging(level, dir_path)
-        file_path = str(dir_path / "app-{time:YYYY-MM-DD}.log")
     elif log_file:
-        # 兼容旧接口
         file_path = Path(log_file)
         file_path.parent.mkdir(parents=True, exist_ok=True)
-        file_path = str(file_path)
+        app_logger = _configure_standard_logging(level, file_path.parent)
     else:
         return
 
-    # 文件输出：按天命名 + 单文件最大10M轮转 + 保留7天
+    def forward_to_standard(message) -> None:
-    logger.add(
+        record = message.record
-        file_path,
+        app_logger.log(record["level"].no, f"{record['name']} | {record['message']}")
-        level=level,
+
-        format="{time:YYYY-MM-DD HH:mm:ss} | {level: <8} | {name}:{function}:{line} | {message}",
+    logger.add(forward_to_standard, level=level, format="{message}")
-        rotation=_should_rotate,     # 超过10M轮转
-        retention="7 days",          # 保留7天
-        compression="zip",           # 旧日志自动压缩节省空间
-        encoding="utf-8",
-    )