diff --git a/docs/zh/online_serving/router_faq.md b/docs/zh/online_serving/router_faq.md index 9c32726f4dc..a431065dbf0 100644 --- a/docs/zh/online_serving/router_faq.md +++ b/docs/zh/online_serving/router_faq.md @@ -5,6 +5,7 @@ 本文档基于 [Golang Router](https://github.com/PaddlePaddle/FastDeploy/tree/develop/fastdeploy/golang_router) 的代码实现，汇总了 Router 在使用过程中常见的日志信息、返回输出及问题排查方法，帮助用户快速定位和解决问题。 Router 的基本使用方式请参考 [负载均衡调度 Router](router.md)。 +如需按“日志定位 + troubleshoot skill”流程化排查，请参考 [Router 问题排查实战手册](router_troubleshoot_playbook.md)。 ## 常见日志分析 diff --git a/docs/zh/online_serving/router_troubleshoot_playbook.md b/docs/zh/online_serving/router_troubleshoot_playbook.md new file mode 100644 index 00000000000..0ccee9c6d55 --- /dev/null +++ b/docs/zh/online_serving/router_troubleshoot_playbook.md @@ -0,0 +1,190 @@ +# Router 问题排查实战手册（日志定位 + troubleshoot skill） + +本文档结合以下两部分信息整理： +- Router 常见问题与日志语义：[`docs/zh/online_serving/router_faq.md`](router_faq.md) +- `fastdeploy/golang_router/.claude/skills/troubleshoot` 的脚本能力与使用方式 + +目标：给出一套可落地的排查流程，帮助你从“现象”快速定位到“日志证据”和“处理建议”。 + +--- + +## 1. 先定范围：全量 / 尾部 / 指定时间段 + +建议先根据问题发生时间选择分析范围（这是和分析模式并列的维度）： + +- **全量分析**：适合历史慢性问题、趋势问题。 +- **尾部分析（`--tail`）**：适合刚发生的故障，优先看最近 N 行或 N 分钟。 +- **指定时间段（`--start/--end`）**：适合已知故障窗口（例如 14:05~14:20）。 + +> 说明：`--tail` 与 `--start/--end` 互斥，二选一。 + +--- + +## 2. 先看健康与注册，再看调度与请求 + +根据 `router_faq.md` 的建议，先确认“有没有可用实例”，再看“请求是否调度成功”。 + +### 2.1 健康与注册检查（必做） + +```bash +# 已注册实例列表 +curl -X GET http://{router_url}/registered + +# 已注册实例数量 +curl -X GET http://{router_url}/registered_number + +# 从 Router 机器检查后端健康 +curl -X GET http://{server_url}/health +``` + +重点日志关键词： +- 健康移除：`Removed unhealthy ... instance` +- 注册失败：`Failed to register instance` +- 健康检查失败：`failed to send request to ...` / `Server ... is not healthy` + +若实例都不健康或未注册，后续 502/503 多数是结果，不是根因。 + +### 2.2 调度失败检查 + +常见错误： +- `Failed to select worker` +- `Failed to select worker pair` +- `No available prefill/decode workers` + +这类问题先确认： +1) 注册数量是否为 0； +2) 调度策略与部署模式是否匹配； +3) `fd_metrics_score` 依赖的 `/metrics` 是否可访问。 + +### 2.3 请求链路与后端请求失败 + +常见日志： +- `Failed to connect to backend service` +- `Request failed (attempt n/max)` +- `Decode/Prefill/Backend request failed for {url}` +- `Panic recovered` + +这类问题通常需要结合 trace（ID 级别）看完整链路。 + +--- + +## 3. 使用 troubleshoot skill 的标准方式 + +脚本入口（在 `fastdeploy/golang_router/` 下）： + +```bash +SCRIPTS=.claude/skills/troubleshoot/scripts +python3 $SCRIPTS/troubleshoot.py [options] +``` + +### 3.1 全量体检（默认推荐首轮） + +```bash +python3 $SCRIPTS/troubleshoot.py +``` + +会同时输出：errors / latency / health / cache / load 的综合结果。 + +### 3.2 指定维度分析（精准打点） + +```bash +python3 $SCRIPTS/troubleshoot.py --errors +python3 $SCRIPTS/troubleshoot.py --latency +python3 $SCRIPTS/troubleshoot.py --health +python3 $SCRIPTS/troubleshoot.py --cache +python3 $SCRIPTS/troubleshoot.py --load +``` + +### 3.3 请求追踪（ID 级排查） + +```bash +# 单个 ID +python3 $SCRIPTS/troubleshoot.py --trace + +# 多个 ID +python3 $SCRIPTS/troubleshoot.py --trace "id1,id2,id3" +``` + +trace 会展示： +- 匹配到的 tag 类型（request_id / trace_id / session_id / req_id） +- 生命周期完整性 +- 事件链（含原始日志 RAW） +- 仅 request_id / 仅 session_id / 仅 trace_id 的统计 +- 各标签组合形式（detail 中给出组合与对应 ID） + +### 3.4 范围过滤与 trace 组合 + +当你要“在某个时间窗内追踪某个 ID”时，使用范围参数和 trace 组合： + +```bash +python3 $SCRIPTS/troubleshoot.py --start "2026/04/13 14:05:00" --end "2026/04/13 14:20:00" --trace "" +``` + +这符合“范围维度（全量/尾部/时间段）”与“模式维度（含 trace）”分离的使用方式。 + +--- + +## 4. 一套可复制的故障定位流程 + +### 步骤 A：确认故障窗口与错误现象 +- 收集用户报错时间、HTTP 状态码（502/503/500/400）和请求路径。 + +### 步骤 B：先跑时间窗综合分析 +```bash +python3 $SCRIPTS/troubleshoot.py --start "HH:MM:SS" --end "HH:MM:SS" +``` +- 看 STATUS（HEALTHY / DEGRADED / CRITICAL）。 +- 优先看 errors、health 章节，判断是否是后端健康/注册问题。 + +### 步骤 C：按症状进入专项 +- 502/503：`--errors --health --load` +- 延迟突增：`--latency --load --cache` +- 单请求失败：`--trace `（可叠加步骤 B 的时间窗） + +### 步骤 D：在 detail 文件中取证 +报告目录默认： +`skill_output/troubleshoot//` + +重点文件： +- `summary/troubleshoot_report.md` +- `detail/trace_.md` +- `detail/health_events.md` +- `detail/load_select_release.md` + +--- + +## 5. 现象到日志的快速映射 + +| 现象 | 优先看日志/关键词 | 推荐命令 | +|---|---|---| +| 503 无可用 worker | `No available prefill/decode workers`, `Removed unhealthy ...` | `--health --errors` | +| 502 调度失败 | `Failed to select worker`, `Failed to select worker pair` | `--errors --health --load` | +| 502 后端连接失败 | `Failed to connect to backend service`, `Request failed (attempt ...)` | `--errors --trace ` | +| 请求卡住/链路不完整 | 有 select 无 release、无 `Request completed successfully.` | `--trace ` | +| 延迟抖动 | HTTP latency、`[stats] total_running...` | `--latency --load --cache` | + +--- + +## 6. 常见误区 + +1. **只看 502/503 响应，不看健康与注册日志**：容易把“结果”当“根因”。 +2. **不限定时间窗口**：日志噪音大，容易误判。 +3. **trace 只看结构化事件，不看 RAW**：可能漏掉关键上下文（例如同一秒的 WARN/ERROR 细节）。 +4. **把范围维度和模式维度混在一起**：建议先定范围（全量/尾部/时间段），再定模式（完整/多维/trace）。 + +--- + +## 7. 推荐排查命令模板 + +```bash +# 模板 1：故障窗口综合体检 +python3 $SCRIPTS/troubleshoot.py --start "YYYY/MM/DD HH:MM:SS" --end "YYYY/MM/DD HH:MM:SS" + +# 模板 2：最近 30 分钟快速巡检 +python3 $SCRIPTS/troubleshoot.py --tail 30m + +# 模板 3：单请求深挖（配合时间窗） +python3 $SCRIPTS/troubleshoot.py --start "HH:MM:SS" --end "HH:MM:SS" --trace "" +``` + +如果你已经知道故障集中在特定 ID，优先从模板 3 入手，然后回到模板 1 看全局背景。 diff --git a/fastdeploy/golang_router/.claude/skills/troubleshoot/SKILL.md b/fastdeploy/golang_router/.claude/skills/troubleshoot/SKILL.md index 7f7a5793e91..2ea74156c82 100644 --- a/fastdeploy/golang_router/.claude/skills/troubleshoot/SKILL.md +++ b/fastdeploy/golang_router/.claude/skills/troubleshoot/SKILL.md @@ -55,10 +55,13 @@ IMPORTANT: 执行前务必先读取 references/log_patterns.md 了解日志格 必须使用 **AskUserQuestion 的离散选项**（不要只发纯文本编号）： - 选项 1: `完整分析（默认）` — 运行所有维度（errors + latency + health + cache + load） - 选项 2: `单维度/多维度分析` — 选择特定维度（errors / latency / health / cache / load），可选多个 -- 选项 3: `请求追踪` — 追踪特定请求 ID（需提供 ID） +- 选项 3: `请求追踪` — 追踪特定请求 ID 如果用户未选择，默认使用完整分析。 +当用户选择“请求追踪”选项时，AskUserQuestion 的选项文案应直接提示可输入： +- `trace_id/request_id/session_id`（逗号分隔多 ID） + ### 4. 输出目录 诊断报告默认保存到 `skill_output/troubleshoot//`（自动按运行时间创建子目录）。 用户可通过 `--output` 指定**基目录**，脚本会继续在其下创建 `/summary` 与 `/detail`，避免覆盖历史明细。 diff --git a/fastdeploy/golang_router/.claude/skills/troubleshoot/scripts/analyzers/trace.py b/fastdeploy/golang_router/.claude/skills/troubleshoot/scripts/analyzers/trace.py index 24af9a23500..37006121994 100644 --- a/fastdeploy/golang_router/.claude/skills/troubleshoot/scripts/analyzers/trace.py +++ b/fastdeploy/golang_router/.claude/skills/troubleshoot/scripts/analyzers/trace.py @@ -112,15 +112,21 @@ def analyze_trace(log_file, trace_ids, tail=None): sr_check = match_select_release(all_lines) diagnoses = _diagnose_trace(events, lifecycle_complete, sr_check) + tag_coverage = _build_id_coverage_stats(all_lines) + tag_combos = _build_id_combo_stats(all_lines) + matched_tags = _detect_matched_tags(all_lines, tid) traces[tid] = { "events": events, "lifecycle_complete": lifecycle_complete, "diagnoses": diagnoses, "sr_check": sr_check, - "matched_tag": "session_id" if is_session else "request_id/trace_id", + "matched_tag": _format_matched_tag(matched_tags), + "matched_tags": matched_tags, "related_ids": { "request_ids": sorted(related_request_ids) if is_session else [], }, + "id_coverage": tag_coverage, + "id_combos": tag_combos, } total_traced = len(traces) @@ -152,13 +158,14 @@ def _parse_event_chain(lines): "path": http["path"], "status": http["status"], "latency_ms": http["latency_ms"], + "raw": line.strip(), } ) continue # Parsing completed if PARSING_COMPLETE_RE.search(line): - events.append({"ts": ts, "type": "PARSING_COMPLETE", "tags": tags}) + events.append({"ts": ts, "type": "PARSING_COMPLETE", "tags": tags, "raw": line.strip()}) continue # Cache-aware strategy @@ -172,6 +179,7 @@ def _parse_event_chain(lines): "strategy": strategy.get("strategy"), "selected": strategy.get("selected", ""), "selected_hitRatio": strategy.get("selected_hitRatio", 0), + "raw": line.strip(), } ) continue @@ -186,6 +194,7 @@ def _parse_event_chain(lines): "tags": tags, "worker_type": m.group(1) or "unknown", "worker": m.group(2), + "raw": line.strip(), } ) continue @@ -200,6 +209,7 @@ def _parse_event_chain(lines): "tags": tags, "worker_type": m.group(1) or "unknown", "worker": m.group(2), + "raw": line.strip(), } ) continue @@ -214,6 +224,7 @@ def _parse_event_chain(lines): "tags": tags, "worker": m.group(1), "tokens": int(m.group(2)), + "raw": line.strip(), } ) continue @@ -221,39 +232,45 @@ def _parse_event_chain(lines): # Prefill events m = PREFILL_FIRST_CHUNK_RE.search(line) if m: - events.append({"ts": ts, "type": "PREFILL_FIRST_CHUNK", "tags": tags, "worker": m.group(1)}) + events.append({"ts": ts, "type": "PREFILL_FIRST_CHUNK", "tags": tags, "worker": m.group(1), "raw": line.strip()}) continue m = PREFILL_DONE_RE.search(line) if m: - events.append({"ts": ts, "type": "PREFILL_DONE", "tags": tags, "worker": m.group(1)}) + events.append({"ts": ts, "type": "PREFILL_DONE", "tags": tags, "worker": m.group(1), "raw": line.strip()}) continue m = PREFILL_ERROR_RE.search(line) if m: - events.append({"ts": ts, "type": "PREFILL_ERROR", "tags": tags, "error": m.group(1), "worker": m.group(2)}) + events.append( + {"ts": ts, "type": "PREFILL_ERROR", "tags": tags, "error": m.group(1), "worker": m.group(2), "raw": line.strip()} + ) continue m = PREFILL_DEFER_RE.search(line) if m: - events.append({"ts": ts, "type": "PREFILL_DEFER_RELEASE", "tags": tags, "worker": m.group(1)}) + events.append( + {"ts": ts, "type": "PREFILL_DEFER_RELEASE", "tags": tags, "worker": m.group(1), "raw": line.strip()} + ) continue m = PREFILL_ERR_PATH_RE.search(line) if m: - events.append({"ts": ts, "type": "PREFILL_ERROR_PATH_RELEASE", "tags": tags, "worker": m.group(1)}) + events.append( + {"ts": ts, "type": "PREFILL_ERROR_PATH_RELEASE", "tags": tags, "worker": m.group(1), "raw": line.strip()} + ) continue # Request completed if REQUEST_COMPLETE_RE.search(line): - events.append({"ts": ts, "type": "REQUEST_COMPLETE", "tags": tags}) + events.append({"ts": ts, "type": "REQUEST_COMPLETE", "tags": tags, "raw": line.strip()}) continue # ts_ms m = TS_MS_RE.search(line) if m: - events.append({"ts": ts, "type": "TS_MS", "tags": tags, "ts_ms": m.group(1)}) + events.append({"ts": ts, "type": "TS_MS", "tags": tags, "ts_ms": m.group(1), "raw": line.strip()}) continue # Failed to select if FAILED_SELECT_RE.search(line): - events.append({"ts": ts, "type": "FAILED_SELECT", "tags": tags}) + events.append({"ts": ts, "type": "FAILED_SELECT", "tags": tags, "raw": line.strip()}) continue # 按时间排序 @@ -339,6 +356,12 @@ def format_trace_report(result): sections.append(f"### ID: {tid}") if trace.get("matched_tag"): sections.append(f' 匹配类型: {trace["matched_tag"]}') + if trace.get("id_coverage"): + c = trace["id_coverage"] + sections.append( + " ID统计: " + f'request_only={c["request_only"]}, session_only={c["session_only"]}, trace_only={c["trace_only"]}' + ) if trace.get("related_ids", {}).get("request_ids"): sections.append(f' 关联 request_ids: {", ".join(trace["related_ids"]["request_ids"])}') @@ -357,6 +380,19 @@ def format_trace_report(result): detail_lines = [f"# 请求追踪事件链: {tid}", ""] if trace.get("matched_tag"): detail_lines.append(f'匹配类型: {trace["matched_tag"]}') + if trace.get("id_coverage"): + c = trace["id_coverage"] + detail_lines.append("ID覆盖统计:") + detail_lines.append( + f'- only_request_id: {c["request_only"]} | only_session_id: {c["session_only"]} | only_trace_id: {c["trace_only"]}' + ) + if trace.get("id_combos"): + detail_lines.append("") + detail_lines.append("标签组合明细（按唯一ID计数）:") + for item in trace["id_combos"]: + detail_lines.append( + f'- combo={item["combo"]} | count={item["count"]} | ids={", ".join(item["ids"])}' + ) if trace.get("related_ids", {}).get("request_ids"): detail_lines.append(f'关联 request_ids: {", ".join(trace["related_ids"]["request_ids"])}') detail_lines.append(f"生命周期: {status}") @@ -379,7 +415,11 @@ def format_trace_report(result): line += f' tokens={evt["tokens"]}' if evt.get("error"): line += f' error={evt["error"]}' + if evt.get("ts_ms"): + line += f' ts_ms={evt["ts_ms"]}' detail_lines.append(line) + if evt.get("raw"): + detail_lines.append(f' RAW: {evt["raw"]}') detail_lines.append("") detail_dict[tid] = "\n".join(detail_lines) @@ -413,3 +453,84 @@ def _grep_lines(log_file, pattern, tail=None): def _shell_quote(s): return "'" + s.replace("'", "'\\''") + "'" + + +def _detect_matched_tags(lines, target_id): + matched = set() + for line in lines: + tags = extract_tags(line) + for key in ("request_id", "trace_id", "session_id", "req_id"): + if tags.get(key) == target_id: + matched.add(key) + return sorted(matched) + + +def _format_matched_tag(matched_tags): + if not matched_tags: + return "unknown" + if len(matched_tags) == 1: + return matched_tags[0] + return "+".join(matched_tags) + + +def _build_id_coverage_stats(lines): + request_only_ids = set() + session_only_ids = set() + trace_only_ids = set() + + for line in lines: + tags = extract_tags(line) + req_val = tags.get("request_id") or tags.get("req_id") + session_val = tags.get("session_id") + trace_val = tags.get("trace_id") + has_request = bool(req_val) + has_session = bool(session_val) + has_trace = bool(trace_val) + + if has_request and not has_session and not has_trace: + request_only_ids.add(req_val) + if has_session and not has_request and not has_trace: + session_only_ids.add(session_val) + if has_trace and not has_request and not has_session: + trace_only_ids.add(trace_val) + + return { + "request_only": len(request_only_ids), + "session_only": len(session_only_ids), + "trace_only": len(trace_only_ids), + } + + +def _build_id_combo_stats(lines): + combo_to_ids = {} + for line in lines: + tags = extract_tags(line) + keys = [] + if tags.get("request_id"): + keys.append("request_id") + if tags.get("req_id"): + keys.append("req_id") + if tags.get("session_id"): + keys.append("session_id") + if tags.get("trace_id"): + keys.append("trace_id") + combo = "+".join(keys) if keys else "no_id_tag" + + ids = [] + if tags.get("request_id"): + ids.append(tags["request_id"]) + if tags.get("req_id"): + ids.append(tags["req_id"]) + if tags.get("session_id"): + ids.append(tags["session_id"]) + if tags.get("trace_id"): + ids.append(tags["trace_id"]) + id_key = "|".join(ids) if ids else "" + + combo_to_ids.setdefault(combo, set()).add(id_key) + + rows = [] + for combo, ids in combo_to_ids.items(): + rows.append({"combo": combo, "count": len(ids), "ids": sorted(ids)}) + rows.sort(key=lambda x: x["count"], reverse=True) + return rows diff --git a/fastdeploy/golang_router/.claude/skills/troubleshoot/scripts/troubleshoot.py b/fastdeploy/golang_router/.claude/skills/troubleshoot/scripts/troubleshoot.py index 803bf6fba43..8378cbe20a1 100644 --- a/fastdeploy/golang_router/.claude/skills/troubleshoot/scripts/troubleshoot.py +++ b/fastdeploy/golang_router/.claude/skills/troubleshoot/scripts/troubleshoot.py @@ -430,6 +430,8 @@ def main(): # 时间范围预过滤（--start 和 --end 可单独或同时指定） import atexit + start_ts = None + end_ts = None if args.start or args.end: start_ts = complete_time_arg(args.start, log_file, is_end=False) if args.start else None end_ts = complete_time_arg(args.end, log_file, is_end=True) if args.end else None