feat: improve sub2api recent error analysis

This commit is contained in:
Codex
2026-07-14 07:07:48 +02:00
parent b9ede0471e
commit da37a96424
5 changed files with 241 additions and 4 deletions
@@ -12,6 +12,11 @@
- `--platform <name>` 可筛选平台;省略分组参数时继续分析 YAML 当前 Codex pool
- 默认输出使用 Kubernetes 风格紧凑表格;机器读取必须显式使用 `--json``--full``--raw`
- dashboard 请求量和客户错误率按分组精确统计;
- 指定分组下钻同时返回原生 `openai-token-stats` 模型时延与 `request-errors` 客户错误画像:
- 模型时延只提供模型维度的平均 TTFT、平均总耗时和首 token 覆盖率;
- 客户错误画像提供模型、账号、状态码、同步/流式、阶段、入口和精确请求路径分布;
- 原生接口没有账号维度 TTFT 时禁止从错误账号分布推导账号 TTFT;
- 默认只给有界 request ID 索引,使用 `trace` 做精确下钻;
- 账号被多个分组共享时,账号级 upstream-errors 和缺少 `group_id` 的 runtime 事件属于共享证据,禁止跨分组相加;
- dashboard overview 提供请求分母和错误率;
- dashboard overview 的 `ttft` 提供成功流式请求的首 token 分位数,`duration` 提供成功请求总耗时分位数;二者不能互相替代;
@@ -109,6 +114,8 @@ bun scripts/cli.ts platform-infra sub2api codex-pool cleanup-probes --target D60
`trace --request-id <requestId>` 是只读 request 追溯报表,不触发 probe、不修改账号。命令优先使用原生 `/admin/ops/requests` 获取请求结果,并使用 `/admin/ops/system-logs` 获取 request-id 索引事件;target runtime 日志只补原生索引未保留的邻近事件。报表显式输出 target、runtime mode、主数据源、上下文数据源和读取状态。默认输出请求开始/最终状态、failover、`account_select_failed``forward_failed`、窗口内 `account_temp_unschedulable`、admin schedulable 写入计数和当前账号快照。`forward_failed` 与 HTTP 200 并存且没有 failover 时,结果标记为 `degraded`,不能解释为完整流式成功;`reason=failover-attempted-no-candidate` 表示 Sub2API 已进入自动切号,但排除当前失败账号后没有可用候选。需要机器处理时使用 `--raw`,需要原始匹配行时加 `--show-lines`
近期故障分析默认使用短窗口,并优先接受原生 Ops 证据。`trace` 在原生 requests 详情缺失时可在同一 `--since` 窗口内查询原生 request-errors;只有原生 system-log 索引缺失时才使用 runtime 日志补事件。历史日志已过保留期不构成运行面缺陷,也不应阻塞近期根因判断。
`trace` 的时间线以原生索引事件时间戳为主。原生 request 记录只有完成时间、但最终日志带 `latency_ms` 时,命令用“完成时间减总耗时”重建参考起点,并披露首次 failover、选号失败和最终响应相对耗时。Sub2API Ops 没有客户 deadline 时,客户剩余时间必须显示不可用,不能用 `latency_ms` 推断。
对已支持的 k3s target`sync --confirm``validate` 和 sentinel 操作可能超过单次 SSH/runtime 短连接窗口;远端 job/poll 边界见 [sentinel.md](sentinel.md)。
@@ -0,0 +1,68 @@
# R2.2.6 任务报告
## 结果
- 完成纯分析 CLI 增强,未修改 Sub2API 配置、账号 runtime、YAML 或运行面。
- `runtime errors --all-groups` 默认使用 Kubernetes 风格概要表,支持所有分组概览和 `--group <name-or-id>` 精确下钻。
- 指定分组详情新增原生 `openai-token-stats` 模型时延表,以及原生 `request-errors` 的模型、账号、状态、同步/流式、阶段、入口和精确路径分布。
- 客户错误画像由 CLI 自动读取原生分页并完成统计,只对 request ID 样本做有界渐进披露,不要求用户手工调整 limit。
- `trace` 继续以原生 requests 和 system-logs 为主;requests 缺记录时只在同一 `--since` 窗口查询原生 request-errorsruntime 日志仅补原生索引缺失的事件。
## 最近 60 分钟全分组证据
- 三个分组合计约 468 个请求、11 个客户可见错误,客户错误率约 2.35%,上游错误率约 4.70%。
- `unidesk-codex-pool`:约 61 至 67 个请求、7 个客户错误,窗口滚动错误率约 10.45% 至 11.48%。
- `自用`:407 个请求、4 个客户错误,错误率 0.98%。
- `grok`:窗口内无流量、无错误。
- 查询时并发约 8/218、队列为 0;当前快照不能代表错误瞬间,但没有证据支持把全局并发不足作为近期主因。
## 分组根因
- `unidesk-codex-pool` 的 7 个客户错误全部是:
- 模型 `gpt-5.6-luna`
- 账号 27
- 同步 `/v1/responses`
- 上游阶段;
- 5 个 502、2 个 503。
- `自用` 的 4 个客户错误全部是:
- 模型 `gpt-5.6-sol`
- 流式 `/responses`
- 账号 15 占 3 个 504,账号 27 占 1 个 502。
- 近期失败不是所有模型、账号和路径均匀恶化,而是两个窄错误簇。
## request trace 证据
- `c76b05df-ad84-4055-bb5a-d363a77e94a1`:约 197.056 秒后账号 27 返回 503,首次 failover、下一次选号失败和最终 502 发生在同一毫秒,选号错误为 `context canceled`
- `2c1211b5-1f9f-441a-9ef8-1f80795097cd`:约 50.863 秒后账号 27 返回 502failover 与 `context canceled` 同时发生。
- `d66d7ea7-4e78-475c-8f93-b315435b79f7`:约 1772.971 秒后账号 15 返回上游 504,随后立即 `context canceled` 并包装成最终 502。
- `4ee54daa-f41c-4f50-bd72-11080c38e299`:约 730.835 秒后账号 27 返回 502,约 1 毫秒后 `context canceled`
- 四个近期代表请求都已进入 failover;临时不可调度规则也有真实命中。直接传播点是 failover 开始时原请求上下文已经取消,不是缺少规则或没有触发切号。
## v0.1.153 官方源码判断
- OpenAI Responses handler 的转发和下一次账号选择都复用 `c.Request.Context()`
- 收到 `UpstreamFailoverError` 后 handler 记录失败账号并直接继续选号;若客户请求上下文已经取消,下一次选择会立即返回 `context canceled`
- `gateway.openai_response_header_timeout` 是 v0.1.153 已有配置,作用范围是等待 OpenAI 上游 HTTP 响应头,不影响响应头之后的流式传输。
- v0.1.153 发布说明没有修复上述 failover 上下文生命周期问题,因此没有证据支持回退版本。
## 候选方案
1. 配置级有界缓解,不涉及 Sub2API 源码变更:
- 设置 OpenAI 专用 response-header timeout,可让真正卡在响应头前的 730 秒或 1773 秒请求更早转成 failover,从而保留切号窗口。
- 它不能解决 50 至 197 秒内已经返回的 502/503,也不能解决流式内容已经提交后的失败。
- 近期 TTFT P99 在分组 2 约 231 至 245 秒、分组 3 约 101 秒;TTFT 不是响应头时延,因此 255/270 秒只能作为排除过低值的观测下限,不能直接视为安全配置。
2. 精确源码方案,涉及 Sub2API 源码变更:
- 增加响应头实际等待时长与首个语义流事件时长,区分响应头前等待和响应头后无事件。
- 在下游尚未提交且客户 deadline 仍有预算时,为单次上游尝试使用更短的 attempt context;超时后在原客户 context 内切号。
- 明确禁止在客户已经断开后继续后台重试,避免无效上游消耗。
3. 窄路由治理:
- 分组 2 优先治理账号 27 的 `gpt-5.6-luna` 能力和错误分类;分组 3 优先治理账号 15/27 的 `gpt-5.6-sol` 长流式等待。
- 不建议用降低全池并发、账号 pinning、扩大临时不可调度时长或版本回退替代根因治理。
## 验证
- `bun --check` 通过:`runtime.ts``remote-python-sync.ts``output.ts`
- `bun test scripts/src/output.test.ts`2 通过、0 失败。
- `git diff --check` 通过。
- 原入口读取验证通过:全分组概要、分组 2/3 详情、四个近期 request trace。
- 超过 3000 行的既有 `remote-python-sync.ts` 拆分已登记为 R2.2.7,本任务未混入大范围机械重构。
@@ -35,6 +35,12 @@
#### R2.2.5 [completed]
增强 Sub2API CLI 的纯分析能力:只读披露实际 OpenAI response-header timeout、TTFT 分位数、长等待请求和 failover 剩余时间窗,并使用原生 admin/ops 数据分析候选配置,不修改 Sub2API 配置、源码或运行面,完成任务后将详细报告写入[任务报告](./details/sub2api-upstream-reliability/R2.2.5_Task_Report.md)。
#### R2.2.6 [completed]
继续纯分析 Sub2API timeout 与 failover:按所有分组、模型、账号和请求类型定位超长 TTFT 与客户错误,区分响应头前等待、流式提交后失败和无候选,评估观测下限是否可能缓解且不做配置实验或运行面变更,完成任务后将详细报告写入[任务报告](./details/sub2api-upstream-reliability/R2.2.6_Task_Report.md)。
#### R2.2.7
按仓库 P0 拆分超过 3000 行的 `remote-python-sync.ts`:把大段内嵌 Python 按 trace、sync/validate 与 sentinel 职责迁入原生模块,单文件收敛到 2000 行以下,并保持受控 CLI 行为与只读诊断契约不变,完成任务后将详细报告写入[任务报告](./details/sub2api-upstream-reliability/R2.2.7_Task_Report.md)。
### R2.3
调查并收敛 Sub2API 原生 system-log 索引未保留策略事件的能力缺口,完成任务后将详细报告写入[任务报告](./details/sub2api-upstream-reliability/R2.3_Task_Report.md)。
@@ -3006,6 +3006,16 @@ def trace_untried_schedulable_accounts(failovers, final_event, account_snapshot)
})
return result
def ops_start_time_for_since(since):
if not isinstance(since, str):
return None
match = re.fullmatch(r"\s*(\d+)\s*([smhd])\s*", since.lower())
if match is None:
return None
value = int(match.group(1))
multiplier = {"s": 1, "m": 60, "h": 3600, "d": 86400}[match.group(2)]
return (datetime.now(timezone.utc) - timedelta(seconds=value * multiplier)).strftime("%Y-%m-%dT%H:%M:%SZ")
def run_trace():
payload = json.loads(base64.b64decode(PAYLOAD_B64).decode("utf-8")) if PAYLOAD_B64 else {}
request_id = payload.get("requestId")
@@ -3032,6 +3042,35 @@ def run_trace():
"returned": len(request_items),
"total": request_data.get("total", len(request_items)) if isinstance(request_data, dict) else len(request_items),
}
if native_request is None:
ops_start_time = ops_start_time_for_since(since)
error_query = f"/api/v1/admin/ops/request-errors?q={request_query}&view=all&page=1&page_size=20"
if isinstance(ops_start_time, str):
error_query += "&start_time=" + quote(ops_start_time, safe="")
error_data = ensure_success(
curl_api("GET", error_query, bearer=token),
"get ops request error fallback",
)
error_items = extract_items(error_data)
native_request = next((item for item in error_items if isinstance(item, dict) and item.get("request_id") == request_id), None)
native_request_status.update({
"fallback": "sub2api-native-admin-ops-request-errors",
"fallbackStartTime": ops_start_time,
"fallbackReturned": len(error_items),
"fallbackTotal": error_data.get("total", len(error_items)) if isinstance(error_data, dict) else len(error_items),
})
if isinstance(native_request, dict):
native_request = dict(native_request)
native_request["kind"] = "error"
error_id = native_request.get("id")
if isinstance(error_id, int):
try:
detail = ensure_success(curl_api("GET", f"/api/v1/admin/ops/request-errors/{error_id}", bearer=token), "get ops request error detail")
if isinstance(detail, dict):
native_request.update(detail)
except Exception:
pass
native_request_status.update({"matched": True, "source": "sub2api-native-admin-ops-request-errors"})
except Exception as exc:
native_request_status = {"status": "unavailable", "reason": text(str(exc), 500)}
@@ -3119,7 +3158,7 @@ def run_trace():
"type": "request-start",
"at": native_request.get("created_at"),
"requestId": native_request.get("request_id"),
"path": None,
"path": native_request.get("request_path") or native_request.get("inbound_endpoint"),
"model": native_request.get("model"),
"accountId": native_request.get("account_id"),
"accountName": account_names_by_id.get(native_request.get("account_id")),
@@ -3137,7 +3176,7 @@ def run_trace():
"type": "final",
"at": native_request.get("created_at"),
"requestId": native_request.get("request_id"),
"path": None,
"path": native_request.get("request_path") or native_request.get("inbound_endpoint"),
"model": native_request.get("model"),
"accountId": native_request.get("account_id"),
"accountName": account_names_by_id.get(native_request.get("account_id")),
@@ -3182,7 +3221,7 @@ def run_trace():
final_elapsed = round((final_epoch - reference_epoch) * 1000) if final_epoch is not None and reference_epoch is not None else None
failover_to_final = final_elapsed - first_failover_elapsed if isinstance(final_elapsed, int) and isinstance(first_failover_elapsed, int) else None
reason = trace_reason(events, final_event)
if not matched:
if not matched and not isinstance(native_request, dict):
outcome = "not-found"
elif isinstance(final_event, dict) and isinstance(final_event.get("statusCode"), int) and final_event.get("statusCode") < 400:
outcome = "degraded" if forward_failures else ("succeeded-with-failover" if failovers else "succeeded")
@@ -3191,7 +3230,7 @@ def run_trace():
else:
outcome = "incomplete"
return {
"ok": proc.returncode == 0 and len(matched) > 0,
"ok": proc.returncode == 0 and (len(matched) > 0 or isinstance(native_request, dict)),
"mode": "trace",
"targetId": TARGET_ID,
"runtimeMode": RUNTIME_MODE,
@@ -172,6 +172,7 @@ function compactRuntimeErrors(value: unknown, options: RuntimeOptions): unknown
overview: nativeOps.overview,
responseHeaderTimeout: nativeOps.responseHeaderTimeout,
requestTiming: nativeOps.requestTiming,
customerErrors: nativeOps.customerErrors,
accountAvailability: {
status: availability.status,
totalAccounts: availabilityGroup.total_accounts,
@@ -325,6 +326,7 @@ function renderRuntimeErrors(lines: string[], runtime: Record<string, unknown>,
const timing = runtimeRecord(nativeOps.requestTiming) ?? {};
const ttft = runtimeRecord(timing.ttft) ?? {};
const duration = runtimeRecord(timing.duration) ?? {};
const customerErrors = runtimeRecord(nativeOps.customerErrors) ?? {};
lines.push(`SUB2API RUNTIME ERRORS ok=${runtime.ok === true ? "true" : "false"} scope=group since=${options.since}`);
lines.push(renderTable([
["GROUP", "ID", "PLATFORM", "REQUESTS", "CLIENT_ERR", "ERR_RATE", "UP_RATE", "BUSINESS_LIMIT", "HEALTH"],
@@ -351,6 +353,32 @@ function renderRuntimeErrors(lines: string[], runtime: Record<string, unknown>,
]),
]));
if (typeof timing.attribution === "string") lines.push(`NOTE: ${timing.attribution}`);
const modelTiming = runtimeRecords(timing.modelTiming);
if (modelTiming.length > 0) lines.push("", "MODEL TIMING", renderTable([
["MODEL", "REQUESTS", "FIRST_TOKEN_ROWS", "COVERAGE", "AVG_TTFT_MS", "AVG_DURATION_MS", "AVG_TOKENS_S"],
...modelTiming.map((item) => [runtimeShort(item.model, 32), runtimeText(item.requestCount), runtimeText(item.requestsWithFirstToken), runtimeRate(item.firstTokenCoverage), runtimeText(item.avgFirstTokenMs), runtimeText(item.avgDurationMs), runtimeText(item.avgTokensPerSec)]),
]));
const errorModels = runtimeRecords(customerErrors.modelBuckets);
const errorAccounts = runtimeRecords(customerErrors.accountBuckets);
const errorDimensions = [
...runtimeRecords(customerErrors.statusBuckets).map((item) => ["status", runtimeText(item.value), runtimeText(item.count)]),
...runtimeRecords(customerErrors.streamBuckets).map((item) => ["mode", runtimeText(item.value), runtimeText(item.count)]),
...runtimeRecords(customerErrors.phaseBuckets).map((item) => ["phase", runtimeText(item.value), runtimeText(item.count)]),
...runtimeRecords(customerErrors.endpointBuckets).map((item) => ["endpoint", runtimeText(item.value), runtimeText(item.count)]),
...runtimeRecords(customerErrors.pathBuckets).map((item) => ["path", runtimeText(item.value), runtimeText(item.count)]),
];
if (errorModels.length > 0) lines.push("", `CUSTOMER ERRORS source=${runtimeText(customerErrors.source)} total=${runtimeText(customerErrors.total)}`, renderTable([
["MODEL", "COUNT"], ...errorModels.map((item) => [runtimeShort(item.value, 40), runtimeText(item.count)]),
]));
if (errorAccounts.length > 0) lines.push(renderTable([
["ACCOUNT_ID", "COUNT"], ...errorAccounts.map((item) => [runtimeText(item.value), runtimeText(item.count)]),
]));
if (errorDimensions.length > 0) lines.push(renderTable([["DIMENSION", "VALUE", "COUNT"], ...errorDimensions]));
const errorSamples = runtimeRecords(customerErrors.samples);
if (errorSamples.length > 0) lines.push("CUSTOMER ERROR INDEX", renderTable([
["REQUEST_ID", "MODEL", "STATUS", "ACCOUNT", "MODE", "PATH", "MESSAGE"],
...errorSamples.map((item) => [runtimeText(item.requestId), runtimeShort(item.model, 26), runtimeText(item.statusCode), runtimeText(item.accountId), runtimeText(item.mode), runtimeShort(item.path, 34), runtimeShort(item.message, 48)]),
]));
lines.push(renderTable([
["ACCOUNTS", "AVAILABLE", "RATE_LIMIT", "ERROR", "IN_USE", "CAPACITY", "QUEUE"],
[
@@ -1206,6 +1234,32 @@ def native_request_timing(token, group_id, platform, overview):
"errorDurationAtLeastCount": error_counts.get(seconds * 1000),
"assessment": "observed-ttft-p99-plus-15s-rounded" if seconds == observed_floor else "ttft-p99-within-candidate" if isinstance(headroom, int) and headroom >= 0 else "ttft-p99-exceeds-candidate" if isinstance(headroom, int) else "insufficient-ttft-evidence",
})
since = str(PAYLOAD.get("since") or "")
token_range = {"30m": "30m", "60m": "1h", "1h": "1h", "24h": "1d", "1d": "1d"}.get(since)
model_timing = []
model_timing_status = "unsupported-window"
if token_range:
response = curl_api("GET", f"/api/v1/admin/ops/dashboard/openai-token-stats?group_id={group_id}&time_range={token_range}&top_n=100{platform_query}", bearer=token)
try:
data = data_of(response, "get OpenAI model token stats")
rows = items_of(data)
for row in rows:
if not isinstance(row, dict):
continue
request_count = row.get("request_count")
first_count = row.get("requests_with_first_token")
model_timing.append({
"model": row.get("model"), "requestCount": request_count,
"requestsWithFirstToken": first_count,
"firstTokenCoverage": round(first_count / request_count, 6) if isinstance(first_count, int) and isinstance(request_count, int) and request_count > 0 else None,
"avgFirstTokenMs": row.get("avg_first_token_ms"), "avgDurationMs": row.get("avg_duration_ms"),
"avgTokensPerSec": row.get("avg_tokens_per_sec"),
})
model_timing.sort(key=lambda item: (-(item.get("avgFirstTokenMs") or -1), str(item.get("model") or "")))
model_timing_status = "available"
except Exception as exc:
model_timing_status = "unavailable"
reason = compact_error(str(exc))
return {
"status": status,
"reason": reason,
@@ -1214,10 +1268,71 @@ def native_request_timing(token, group_id, platform, overview):
"duration": duration,
"observedFloorSeconds": observed_floor,
"errorDurationRecordCount": error_duration_record_count,
"modelTimingStatus": model_timing_status,
"modelTimingWindow": token_range,
"modelTiming": model_timing[:20 if PAYLOAD.get("full") is True else 8],
"candidates": candidates,
"attribution": "TTFT covers successful streaming requests with first_token_ms. Total and error duration are end-to-end request durations, not response-header wait or guaranteed failover lead time. The observed floor is TTFT P99 plus 15 seconds rounded up to 15 seconds; it is not a deployment recommendation. A dash in ERROR_DUR>= means error duration coverage is unavailable.",
}
def native_customer_error_profile(token, group_id, platform):
start_time = quote(since_start_time(PAYLOAD.get("since")), safe="")
platform_query = "&platform=" + quote(str(platform), safe="") if platform else ""
page = 1
page_size = 500
rows = []
total = None
try:
while True:
response = curl_api("GET", f"/api/v1/admin/ops/request-errors?group_id={group_id}&start_time={start_time}&view=all&page={page}&page_size={page_size}{platform_query}", bearer=token)
data = data_of(response, "get customer-visible request errors")
page_rows = items_of(data)
rows.extend(page_rows)
if total is None and isinstance(data, dict) and isinstance(data.get("total"), int):
total = data.get("total")
if not page_rows or len(page_rows) < page_size or (isinstance(total, int) and len(rows) >= total):
break
page += 1
except Exception as exc:
return {"status": "unavailable", "source": "sub2api-native-admin-ops-request-errors", "reason": compact_error(str(exc))}
if total is None:
total = len(rows)
def buckets(key_fn):
counts = {}
for row in rows:
value = key_fn(row) if isinstance(row, dict) else None
label = str(value) if value not in (None, "") else "unknown"
counts[label] = counts.get(label, 0) + 1
return [{"value": key, "count": count} for key, count in sorted(counts.items(), key=lambda item: (-item[1], item[0]))[:20 if PAYLOAD.get("full") is True else 8]]
samples = []
seen = set()
for row in rows:
if not isinstance(row, dict) or not row.get("request_id"):
continue
key = (row.get("requested_model") or row.get("model"), row.get("status_code"), row.get("account_id"), row.get("stream"), row.get("request_path") or row.get("inbound_endpoint"))
if key in seen:
continue
seen.add(key)
samples.append({
"requestId": row.get("request_id"), "model": key[0], "statusCode": key[1], "accountId": key[2],
"mode": "stream" if key[3] is True else "sync" if key[3] is False else "unknown", "path": key[4],
"message": compact_error(row.get("message") or row.get("error_message")),
})
if len(samples) >= (30 if PAYLOAD.get("full") is True else 15):
break
return {
"status": "available", "source": "sub2api-native-admin-ops-request-errors", "total": total,
"returned": len(rows), "pagesRead": page, "recordsTruncated": False,
"modelBuckets": buckets(lambda row: row.get("requested_model") or row.get("model")),
"accountBuckets": buckets(lambda row: row.get("account_id")),
"statusBuckets": buckets(lambda row: row.get("status_code")),
"streamBuckets": buckets(lambda row: "stream" if row.get("stream") is True else "sync" if row.get("stream") is False else "unknown"),
"phaseBuckets": buckets(lambda row: row.get("phase")),
"endpointBuckets": buckets(lambda row: row.get("inbound_endpoint") or row.get("request_path")),
"pathBuckets": buckets(lambda row: row.get("request_path") or row.get("inbound_endpoint")),
"samples": samples,
}
def all_group_error_overview(token, groups):
page_size = 20
cursor = int(PAYLOAD.get("pageToken") or 0)
@@ -1636,6 +1751,7 @@ def observed_runtime_errors(token, accounts, group_id, platform=None):
overview_summary = ((native_ops.get("overview") or {}).get("summary") or {})
native_ops["responseHeaderTimeout"] = runtime_response_header_timeout()
native_ops["requestTiming"] = native_request_timing(token, group_id, platform, overview_summary)
native_ops["customerErrors"] = native_customer_error_profile(token, group_id, platform)
request_total = overview_summary.get("request_count_total")
error_total = overview_summary.get("error_count_total")
if isinstance(request_total, int) and isinstance(error_total, int):
@@ -1771,6 +1887,7 @@ def observed_runtime_errors(token, accounts, group_id, platform=None):
},
"responseHeaderTimeout": native_ops.get("responseHeaderTimeout"),
"requestTiming": native_ops.get("requestTiming"),
"customerErrors": native_ops.get("customerErrors"),
"accountAvailability": {
"status": (native_ops.get("accountAvailability") or {}).get("status"),
"group": availability.get("group"),