feat: expose sub2api timeout timing diagnostics

This commit is contained in:
Codex
2026-07-14 06:51:24 +02:00
parent a91238c200
commit b9ede0471e
6 changed files with 265 additions and 5 deletions
@@ -3145,6 +3145,25 @@ def run_trace():
"latencyMs": native_request.get("duration_ms"),
"source": "sub2api-native-admin-ops-requests",
}
reference_at = request_start.get("at") if isinstance(request_start, dict) else None
reference_epoch = log_time_epoch({"_at": reference_at}) if isinstance(reference_at, str) else first_epoch
reference_source = "request-start" if isinstance(reference_at, str) and reference_epoch is not None else "first-matched-event"
native_duration_ms = native_request.get("duration_ms") if isinstance(native_request, dict) else None
if not isinstance(native_duration_ms, int) and isinstance(final_event, dict):
native_duration_ms = final_event.get("latencyMs")
if (
isinstance(request_start, dict)
and request_start.get("source") == "sub2api-native-admin-ops-requests"
and isinstance(native_duration_ms, int)
and native_duration_ms >= 0
and reference_epoch is not None
):
reference_epoch -= native_duration_ms / 1000
reference_at = datetime.fromtimestamp(reference_epoch, timezone.utc).isoformat().replace("+00:00", "Z")
reference_source = "native-completion-minus-duration"
for event in events:
epoch = log_time_epoch({"_at": event.get("at")}) if isinstance(event.get("at"), str) else None
event["elapsedMs"] = round((epoch - reference_epoch) * 1000) if epoch is not None and reference_epoch is not None else None
failovers = [item for item in events if item.get("type") == "failover"]
select_failures = [item for item in events if item.get("type") == "select-failed"]
upstream_errors = [item for item in events if item.get("type") == "upstream-error"]
@@ -3157,6 +3176,11 @@ def run_trace():
window_select_failures = [item for item in window_events if item.get("type") == "select-failed"]
window_forward_failures = [item for item in window_events if item.get("type") == "forward-failed"]
untried_schedulable_accounts = trace_untried_schedulable_accounts(failovers, final_event or {}, account_snapshot)
first_failover_elapsed = failovers[0].get("elapsedMs") if failovers else None
first_select_failed_elapsed = select_failures[0].get("elapsedMs") if select_failures else None
final_epoch = log_time_epoch({"_at": final_event.get("at")}) if isinstance(final_event, dict) and isinstance(final_event.get("at"), str) else None
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:
outcome = "not-found"
@@ -3220,6 +3244,17 @@ def run_trace():
"diagnostics": {
"failoverBudgetExhausted": failover_budget_exhausted(failovers, final_event or {}),
"untriedSchedulableAccounts": untried_schedulable_accounts,
"timing": {
"referenceAt": reference_at if isinstance(reference_at, str) else (events[0].get("at") if events else None),
"referenceSource": reference_source,
"firstFailoverElapsedMs": first_failover_elapsed,
"firstSelectFailedElapsedMs": first_select_failed_elapsed,
"finalElapsedMs": final_elapsed,
"failoverToFinalMs": failover_to_final,
"clientDeadlineAvailable": False,
"clientDeadlineRemainingMs": None,
"attribution": "Elapsed values come from indexed event timestamps. The client deadline is not present in Sub2API Ops records, so remaining request budget cannot be calculated.",
},
},
"accountSnapshot": account_snapshot,
"accountSnapshotError": account_snapshot_error,
@@ -401,6 +401,8 @@ export function renderTraceReport(
const forwardFailures = recordArray(parsed.forwardFailures);
const tempUnschedulable = recordArray(parsed.tempUnschedulable);
const windowStats = isRecord(parsed.windowStats) ? parsed.windowStats : {};
const diagnostics = isRecord(parsed.diagnostics) ? parsed.diagnostics : {};
const timing = isRecord(diagnostics.timing) ? diagnostics.timing : {};
const logs = isRecord(parsed.logs) ? parsed.logs : {};
const accountSnapshot = recordArray(parsed.accountSnapshot);
const lines: string[] = [];
@@ -439,13 +441,23 @@ export function renderTraceReport(
`events=${textValue(summary.eventCount)}`,
`window=${window.beforeSeconds ?? "?"}s/${window.afterSeconds ?? "?"}s`,
].join(" "));
lines.push(renderTable([
["TIME_REF", "FIRST_FAILOVER_MS", "SELECT_FAILED_MS", "FINAL_MS", "FAILOVER_TO_FINAL_MS", "CLIENT_DEADLINE", "REMAINING_MS"],
[
textValue(timing.referenceSource), textValue(timing.firstFailoverElapsedMs), textValue(timing.firstSelectFailedElapsedMs),
textValue(timing.finalElapsedMs), textValue(timing.failoverToFinalMs), timing.clientDeadlineAvailable === true ? "available" : "unavailable",
textValue(timing.clientDeadlineRemainingMs),
],
]));
if (typeof timing.attribution === "string") lines.push(`NOTE: ${timing.attribution}`);
if (failovers.length > 0) {
lines.push("");
lines.push("FAILOVER");
lines.push(renderTable([
["AT", "ACCOUNT", "UPSTREAM", "SWITCH", "MAX"],
["AT", "ELAPSED_MS", "ACCOUNT", "UPSTREAM", "SWITCH", "MAX"],
...failovers.map((item) => [
shortIso(item.at),
textValue(item.elapsedMs),
formatAccountRef(item),
textValue(item.upstreamStatus),
textValue(item.switchCount),
@@ -457,9 +469,10 @@ export function renderTraceReport(
lines.push("");
lines.push("SELECT-FAILED");
lines.push(renderTable([
["AT", "ERROR", "EXCLUDED"],
["AT", "ELAPSED_MS", "ERROR", "EXCLUDED"],
...selectFailures.map((item) => [
shortIso(item.at),
textValue(item.elapsedMs),
shorten(stringValue(item.error) ?? "-", 56),
textValue(item.excludedAccountCount),
]),
@@ -469,9 +482,10 @@ export function renderTraceReport(
lines.push("");
lines.push("FORWARD-FAILED");
lines.push(renderTable([
["AT", "ACCOUNT", "STATUS", "ERROR"],
["AT", "ELAPSED_MS", "ACCOUNT", "STATUS", "ERROR"],
...forwardFailures.map((item) => [
shortIso(item.at),
textValue(item.elapsedMs),
formatAccountRef(item),
textValue(item.statusCode),
shorten(stringValue(item.error) ?? "-", 72),
@@ -170,6 +170,8 @@ function compactRuntimeErrors(value: unknown, options: RuntimeOptions): unknown
nativeOps: {
source: nativeOps.source,
overview: nativeOps.overview,
responseHeaderTimeout: nativeOps.responseHeaderTimeout,
requestTiming: nativeOps.requestTiming,
accountAvailability: {
status: availability.status,
totalAccounts: availabilityGroup.total_accounts,
@@ -277,6 +279,8 @@ function renderRuntimeErrors(lines: string[], runtime: Record<string, unknown>,
const allGroups = runtimeRecord(runtime.allGroups);
if (allGroups !== null) {
const totals = runtimeRecord(allGroups.pageTotals) ?? {};
const timeout = runtimeRecord(allGroups.responseHeaderTimeout) ?? {};
const timing = runtimeRecord(allGroups.requestTiming) ?? {};
const groups = runtimeRecords(allGroups.groups);
lines.push(`SUB2API RUNTIME ERRORS ok=${runtime.ok === true ? "true" : "false"} scope=all-groups since=${options.since}`);
lines.push(renderTable([
@@ -287,13 +291,22 @@ function renderRuntimeErrors(lines: string[], runtime: Record<string, unknown>,
runtimeRate(totals.upstreamErrorRate), runtimeText(totals.groupsNeedingAttention),
],
]));
lines.push(renderTable([
["OPENAI_HEADER_TIMEOUT", "SOURCE", "GENERIC_TIMEOUT", "GENERIC_APPLIES_TO_OPENAI", "PAGE_MAX_TTFT_P99_MS", "OBSERVED_FLOOR_SECONDS"],
[
timeout.disabled === true ? "disabled" : `${runtimeText(timeout.effectiveSeconds)}s`, runtimeText(timeout.source),
`${runtimeText(timeout.genericResponseHeaderTimeoutSeconds)}s`, runtimeText(timeout.genericAppliesToOpenAI),
runtimeText(timing.maxTtftP99Ms), runtimeText(timing.observedFloorSeconds),
],
]));
if (typeof timing.attribution === "string") lines.push(`NOTE: ${timing.attribution}`);
lines.push("", "GROUPS");
lines.push(renderTable([
["NAME", "ID", "PLATFORM", "STATUS", "REQ", "CLIENT_ERR", "ERR_RATE", "UP_ERR", "UP_RATE", "ACCOUNTS", "AVAILABLE", "USE/CAP", "QUEUE", "ATTN"],
["NAME", "ID", "PLATFORM", "STATUS", "REQ", "CLIENT_ERR", "ERR_RATE", "UP_ERR", "UP_RATE", "TTFT_P99_MS", "DUR_P99_MS", "ACCOUNTS", "AVAILABLE", "USE/CAP", "QUEUE", "ATTN"],
...groups.map((group) => [
runtimeShort(group.groupName, 28), runtimeText(group.groupId), runtimeText(group.platform), runtimeText(group.status),
runtimeText(group.requestCount), runtimeText(group.errorCount), runtimeRate(group.errorRate), runtimeText(group.upstreamErrorCount),
runtimeRate(group.upstreamErrorRate), runtimeText(group.totalAccounts), runtimeText(group.availableCount),
runtimeRate(group.upstreamErrorRate), runtimeText(group.ttftP99Ms), runtimeText(group.durationP99Ms), runtimeText(group.totalAccounts), runtimeText(group.availableCount),
`${runtimeText(group.currentInUse)}/${runtimeText(group.maxCapacity)}`, runtimeText(group.waitingInQueue), group.needsAttention === true ? "yes" : "no",
]),
]));
@@ -308,6 +321,10 @@ function renderRuntimeErrors(lines: string[], runtime: Record<string, unknown>,
const overview = runtimeRecord(nativeOps.overview) ?? {};
const availability = runtimeRecord(nativeOps.accountAvailability) ?? {};
const concurrency = runtimeRecord(nativeOps.concurrency) ?? {};
const timeout = runtimeRecord(nativeOps.responseHeaderTimeout) ?? {};
const timing = runtimeRecord(nativeOps.requestTiming) ?? {};
const ttft = runtimeRecord(timing.ttft) ?? {};
const duration = runtimeRecord(timing.duration) ?? {};
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"],
@@ -317,6 +334,23 @@ function renderRuntimeErrors(lines: string[], runtime: Record<string, unknown>,
runtimeText(overview.businessLimitedCount), runtimeText(overview.healthScore),
],
]));
lines.push(renderTable([
["OPENAI_HEADER_TIMEOUT", "SOURCE", "TTFT_P50_MS", "TTFT_P95_MS", "TTFT_P99_MS", "TTFT_MAX_MS", "DURATION_P99_MS", "DURATION_MAX_MS"],
[
timeout.disabled === true ? "disabled" : `${runtimeText(timeout.effectiveSeconds)}s`, runtimeText(timeout.source),
runtimeText(ttft.p50_ms), runtimeText(ttft.p95_ms), runtimeText(ttft.p99_ms), runtimeText(ttft.max_ms),
runtimeText(duration.p99_ms), runtimeText(duration.max_ms),
],
]));
const candidates = runtimeRecords(timing.candidates);
if (candidates.length > 0) lines.push("", "TIMEOUT CANDIDATES", renderTable([
["SECONDS", "OBSERVED_FLOOR", "TTFT_P99_HEADROOM_MS", "TTFT_P99_BELOW", "ALL_DUR>=", "ERROR_DUR>=", "ASSESSMENT"],
...candidates.map((candidate) => [
runtimeText(candidate.seconds), runtimeText(candidate.observedFloor), runtimeText(candidate.ttftP99HeadroomMs), runtimeText(candidate.ttftP99Below),
runtimeText(candidate.totalDurationAtLeastCount), runtimeText(candidate.errorDurationAtLeastCount), runtimeText(candidate.assessment),
]),
]));
if (typeof timing.attribution === "string") lines.push(`NOTE: ${timing.attribution}`);
lines.push(renderTable([
["ACCOUNTS", "AVAILABLE", "RATE_LIMIT", "ERROR", "IN_USE", "CAPACITY", "QUEUE"],
[
@@ -750,6 +784,69 @@ def runtime_log_lines():
output = proc.stdout + b"\\n" + proc.stderr
return output.decode("utf-8", errors="replace").splitlines()
def app_exec(args):
if RUNTIME_MODE == "host-docker":
return docker(["exec", APP_POD, *args])
return kubectl(["-n", NAMESPACE, "exec", APP_POD, "--", *args])
def app_text(args):
proc = app_exec(args)
return proc.stdout.decode("utf-8", errors="replace").strip() if proc.returncode == 0 else ""
def config_scalar(path, key):
script = r'''awk -v wanted="$2" '
BEGIN { in_gateway=0 }
/^gateway:[[:space:]]*($|#)/ { in_gateway=1; next }
in_gateway && /^[^[:space:]#]/ { exit }
in_gateway && $0 ~ "^[[:space:]]+" wanted ":[[:space:]]*" {
value=$0
sub("^[[:space:]]+" wanted ":[[:space:]]*", "", value)
sub("[[:space:]]*#.*$", "", value)
gsub("^[[:space:]\\\"'\''']+|[[:space:]\\\"'\''']+$", "", value)
print value
exit
}' "$1"'''
return app_text(["sh", "-c", script, "sh", path, key])
def runtime_response_header_timeout():
env_openai = app_text(["sh", "-c", "printenv GATEWAY_OPENAI_RESPONSE_HEADER_TIMEOUT 2>/dev/null || true"])
env_generic = app_text(["sh", "-c", "printenv GATEWAY_RESPONSE_HEADER_TIMEOUT 2>/dev/null || true"])
config_file = app_text(["sh", "-c", "printenv CONFIG_FILE 2>/dev/null || true"])
paths = [value for value in (config_file, "/app/data/config.yaml", "/etc/sub2api/config.yaml", "/app/config.yaml") if value]
config_openai = ""
config_generic = ""
config_source = None
for path in dict.fromkeys(paths):
openai_value = config_scalar(path, "openai_response_header_timeout")
generic_value = config_scalar(path, "response_header_timeout")
if openai_value or generic_value:
config_openai = openai_value
config_generic = generic_value
config_source = path
break
def non_negative_int(value):
try:
parsed = int(str(value).strip())
return parsed if parsed >= 0 else None
except (TypeError, ValueError):
return None
openai_configured = non_negative_int(config_openai)
openai_env = non_negative_int(env_openai)
generic_configured = non_negative_int(config_generic)
generic_env = non_negative_int(env_generic)
effective = openai_configured if openai_configured is not None else openai_env if openai_env is not None else 0
source = "config-file:" + config_source if openai_configured is not None else "process-env" if openai_env is not None else "sub2api-default"
generic = generic_configured if generic_configured is not None else generic_env if generic_env is not None else 600
return {
"effectiveSeconds": effective,
"disabled": effective == 0,
"source": source,
"genericResponseHeaderTimeoutSeconds": generic,
"genericAppliesToOpenAI": False,
"configFileChecked": config_source,
"valuesPrinted": False,
}
def compact_error(value):
if not isinstance(value, str):
return ""
@@ -981,6 +1078,7 @@ def native_ops_snapshot(token, group_id, platform=None):
"business_limited_count", "error_count_sla", "request_count_total", "request_count_sla",
"error_rate", "upstream_error_rate", "upstream_error_count_excl_429_529",
"upstream_429_count", "upstream_529_count",
"duration", "ttft",
)
}
@@ -1062,6 +1160,64 @@ def native_ops_snapshot(token, group_id, platform=None):
"systemLogSink": {"status": sink_result.get("status"), "health": sink if isinstance(sink, dict) else None, "reason": sink_result.get("reason")},
}
def native_request_timing(token, group_id, platform, overview):
start_time = quote(since_start_time(PAYLOAD.get("since")), safe="")
platform_query = "&platform=" + quote(str(platform), safe="") if platform else ""
base = f"group_id={group_id}&start_time={start_time}{platform_query}"
all_counts = {}
error_counts = {}
status = "available"
reason = None
duration = overview.get("duration") if isinstance(overview.get("duration"), dict) else {}
ttft = overview.get("ttft") if isinstance(overview.get("ttft"), dict) else {}
ttft_p99 = ttft.get("p99_ms")
observed_floor = max(60, ((ttft_p99 + 29999) // 15000) * 15) if isinstance(ttft_p99, int) else None
candidate_seconds = sorted(set([30, 45, 60] + ([observed_floor] if isinstance(observed_floor, int) else [])))
error_duration_response = curl_api("GET", f"/api/v1/admin/ops/requests?{base}&page=1&page_size=1&kind=error&min_duration_ms=0", bearer=token)
try:
error_duration_data = data_of(error_duration_response, "get error duration coverage")
error_duration_record_count = error_duration_data.get("total") if isinstance(error_duration_data, dict) else None
except Exception as exc:
error_duration_record_count = None
status = "unavailable"
reason = compact_error(str(exc))
for seconds in candidate_seconds:
threshold = seconds * 1000
for kind, target in ((None, all_counts), ("error", error_counts)):
kind_query = "&kind=error" if kind else ""
response = curl_api("GET", f"/api/v1/admin/ops/requests?{base}&page=1&page_size=1&min_duration_ms={threshold}{kind_query}", bearer=token)
try:
data = data_of(response, "get long request count")
value = data.get("total") if isinstance(data, dict) else None
target[threshold] = None if kind == "error" and error_duration_record_count == 0 else value
except Exception as exc:
status = "unavailable"
reason = compact_error(str(exc))
target[threshold] = None
candidates = []
for seconds in candidate_seconds:
headroom = seconds * 1000 - ttft_p99 if isinstance(ttft_p99, int) else None
candidates.append({
"seconds": seconds,
"observedFloor": seconds == observed_floor,
"ttftP99HeadroomMs": headroom,
"ttftP99Below": headroom >= 0 if isinstance(headroom, int) else None,
"totalDurationAtLeastCount": all_counts.get(seconds * 1000),
"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",
})
return {
"status": status,
"reason": reason,
"source": "sub2api-native-admin-ops-dashboard-and-requests",
"ttft": ttft,
"duration": duration,
"observedFloorSeconds": observed_floor,
"errorDurationRecordCount": error_duration_record_count,
"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 all_group_error_overview(token, groups):
page_size = 20
cursor = int(PAYLOAD.get("pageToken") or 0)
@@ -1120,6 +1276,8 @@ def all_group_error_overview(token, groups):
"upstreamErrorCount": upstream_error_count,
"upstreamErrorRate": overview.get("upstream_error_rate"),
"businessLimitedCount": business_limited,
"ttftP99Ms": ((overview.get("ttft") or {}).get("p99_ms") if isinstance(overview.get("ttft"), dict) else None),
"durationP99Ms": ((overview.get("duration") or {}).get("p99_ms") if isinstance(overview.get("duration"), dict) else None),
"totalAccounts": availability_group.get("total_accounts"),
"availableCount": availability_group.get("available_count"),
"rateLimitCount": availability_group.get("rate_limit_count"),
@@ -1138,6 +1296,9 @@ def all_group_error_overview(token, groups):
next_token = str(page[-1]["id"]) if len(remaining) > page_size and page else None
totals["errorRate"] = round(totals["errorCount"] / totals["requestCount"], 6) if totals["requestCount"] > 0 else None
totals["upstreamErrorRate"] = round(totals["upstreamErrorCount"] / totals["requestCount"], 6) if totals["requestCount"] > 0 else None
ttft_p99_values = [item.get("ttftP99Ms") for item in summaries if isinstance(item.get("ttftP99Ms"), int)]
max_ttft_p99 = max(ttft_p99_values) if ttft_p99_values else None
observed_floor = max(60, ((max_ttft_p99 + 29999) // 15000) * 15) if isinstance(max_ttft_p99, int) else None
return {
"scope": "all-groups-overview",
"window": {"since": PAYLOAD.get("since")},
@@ -1148,6 +1309,13 @@ def all_group_error_overview(token, groups):
"pageToken": str(cursor) if cursor > 0 else None,
"nextPageToken": next_token,
"pageTotals": totals,
"responseHeaderTimeout": runtime_response_header_timeout(),
"requestTiming": {
"maxTtftP99Ms": max_ttft_p99,
"observedFloorSeconds": observed_floor,
"scope": "returned-groups-page",
"attribution": "The observed floor is the maximum returned-group TTFT P99 plus 15 seconds rounded up to 15 seconds. It is analytical only and must not be treated as a safe timeout.",
},
"groups": summaries,
"disclosure": "Page totals cover only returned groups. Follow nextPageToken for remaining groups and use --group for account root causes and request indexes.",
}
@@ -1466,6 +1634,8 @@ def observed_runtime_errors(token, accounts, group_id, platform=None):
effectiveness = policy_effectiveness(lines, accounts, system_log_source.get("source"), group_id)
effectiveness["sourceStatus"] = system_log_source
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)
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):
@@ -1599,6 +1769,8 @@ def observed_runtime_errors(token, accounts, group_id, platform=None):
"upstreamErrorRate": overview.get("upstream_error_rate"),
"businessLimitedCount": overview.get("business_limited_count"),
},
"responseHeaderTimeout": native_ops.get("responseHeaderTimeout"),
"requestTiming": native_ops.get("requestTiming"),
"accountAvailability": {
"status": (native_ops.get("accountAvailability") or {}).get("status"),
"group": availability.get("group"),