Files
Aether/apps/aether-gateway/src/executor/candidate_loop.rs
T

918 lines
31 KiB
Rust
Raw Normal View History

2026-05-02 13:23:54 +08:00
use aether_ai_serving::{
run_ai_attempt_loop, AiAttemptLoopOutcome, AiAttemptLoopPort, AiExecutionAttempt,
UPSTREAM_IS_STREAM_KEY,
2026-05-02 13:23:54 +08:00
};
use aether_data_contracts::repository::candidates::RequestCandidateStatus;
use aether_scheduler_core::{
parse_request_candidate_report_context, SchedulerRequestCandidateStatusUpdate,
};
2026-05-02 13:23:54 +08:00
use async_trait::async_trait;
use axum::body::Body;
use axum::http::Response;
use tokio::time::{timeout, Duration};
use tracing::{debug, warn, Instrument};
2026-05-03 20:14:29 +08:00
use crate::ai_serving::LocalExecutionAttemptSource;
use crate::clock::current_unix_ms;
use crate::control::GatewayControlDecision;
use crate::execution_runtime::{execute_execution_runtime_stream, execute_execution_runtime_sync};
use crate::executor::{build_local_execution_exhaustion, LocalExecutionRequestOutcome};
2026-05-11 00:12:05 +08:00
use crate::handlers::shared::provider_pool::release_admin_provider_pool_key_lease;
use crate::log_ids::short_request_id;
use crate::orchestration::local_execution_candidate_metadata_from_report_context;
use crate::privacy::RedactionExecutionCandidateId;
use crate::request_candidate_runtime::{
record_local_request_candidate_status, RequestCandidateRuntimeWriter,
};
use crate::{AppState, GatewayError};
2026-05-25 20:09:37 +08:00
const DEFAULT_STREAM_FIRST_BYTE_WATCHDOG_TIMEOUT_MS: u64 = 30_000;
const DEFAULT_NON_STREAM_CANDIDATE_WATCHDOG_TIMEOUT_MS: u64 = 300_000;
fn attach_redaction_execution_candidate(response: &mut Response<Body>, candidate_id: Option<&str>) {
if let Some(candidate_id) = candidate_id
.map(str::trim)
.filter(|value| !value.is_empty())
{
response
.extensions_mut()
.insert(RedactionExecutionCandidateId::new(candidate_id));
}
}
pub(crate) async fn execute_sync_plan_and_reports<T>(
state: &AppState,
parts: &http::request::Parts,
trace_id: &str,
decision: &GatewayControlDecision,
plan_kind: &str,
plan_and_reports: Vec<T>,
) -> Result<LocalExecutionRequestOutcome, GatewayError>
where
2026-05-02 13:23:54 +08:00
T: AiExecutionAttempt + Send + Sync + 'static,
{
let candidate_count = plan_and_reports.len();
let first_provider = plan_and_reports
.first()
2026-05-02 13:23:54 +08:00
.and_then(|item| item.execution_plan().provider_name.as_deref())
.unwrap_or("-")
.to_string();
let span = tracing::debug_span!(
"candidates",
trace_id = %trace_id,
plan_kind,
candidate_count,
);
async move {
tracing::debug!(
event_name = "candidate_loop_started",
log_type = "event",
trace_id = %trace_id,
plan_kind,
candidate_count,
first_provider = first_provider.as_str(),
"candidate loop started"
);
2026-05-02 13:23:54 +08:00
let port = SyncAttemptLoopPort {
state,
parts,
trace_id,
decision,
plan_kind,
};
2026-05-02 13:23:54 +08:00
match run_ai_attempt_loop(&port, plan_and_reports).await? {
AiAttemptLoopOutcome::Responded(response) => {
Ok(LocalExecutionRequestOutcome::responded(response))
}
AiAttemptLoopOutcome::Exhausted(exhaustion) => {
Ok(LocalExecutionRequestOutcome::Exhausted(exhaustion))
}
AiAttemptLoopOutcome::NoPath => Ok(LocalExecutionRequestOutcome::NoPath),
}
}
.instrument(span)
.await
}
2026-05-03 20:14:29 +08:00
pub(crate) async fn execute_sync_attempt_source<T, S>(
state: &AppState,
parts: &http::request::Parts,
trace_id: &str,
decision: &GatewayControlDecision,
plan_kind: &str,
mut source: S,
) -> Result<LocalExecutionRequestOutcome, GatewayError>
where
T: AiExecutionAttempt + Send + Sync + 'static,
S: LocalExecutionAttemptSource<T>,
{
let span = tracing::debug_span!("candidates", trace_id = %trace_id, plan_kind);
async move {
tracing::debug!(
event_name = "candidate_loop_started",
log_type = "event",
trace_id = %trace_id,
plan_kind,
"dynamic candidate loop started"
);
let port = SyncAttemptLoopPort {
state,
parts,
trace_id,
decision,
plan_kind,
};
2026-05-22 23:57:38 +08:00
run_dynamic_attempt_loop(
&port,
&mut source,
trace_id,
plan_kind,
state
.frontdoor_runtime_guards
.local_execution_planning_timeout,
)
.await
2026-05-03 20:14:29 +08:00
}
.instrument(span)
.await
}
2026-05-02 13:23:54 +08:00
struct SyncAttemptLoopPort<'a> {
state: &'a AppState,
parts: &'a http::request::Parts,
trace_id: &'a str,
decision: &'a GatewayControlDecision,
plan_kind: &'a str,
}
#[async_trait]
impl<T> AiAttemptLoopPort<T> for SyncAttemptLoopPort<'_>
where
T: AiExecutionAttempt + Send + Sync + 'static,
{
type Response = Response<Body>;
type Exhaustion = crate::executor::LocalExecutionExhaustion;
type Error = GatewayError;
async fn execute_attempt(&self, attempt: &T) -> Result<Option<Self::Response>, Self::Error> {
let mut response = execute_execution_runtime_sync(
2026-05-02 13:23:54 +08:00
self.state,
self.parts.uri.path(),
attempt.execution_plan().clone(),
self.trace_id,
self.decision,
self.plan_kind,
attempt.report_kind(),
attempt.report_context(),
)
.await?;
if let Some(response) = response.as_mut() {
attach_redaction_execution_candidate(
response,
attempt.execution_plan().candidate_id.as_deref(),
);
}
Ok(response)
2026-05-02 13:23:54 +08:00
}
async fn mark_unused_attempts(&self, attempts: Vec<T>) -> Result<(), Self::Error> {
mark_unused_local_candidates(self.state, attempts).await;
Ok(())
}
async fn build_exhaustion(
&self,
last_plan: aether_contracts::ExecutionPlan,
last_report_context: Option<serde_json::Value>,
) -> Result<Self::Exhaustion, Self::Error> {
2026-05-09 01:21:26 +08:00
warn!(
event_name = "candidate_loop_exhausted",
log_type = "ops",
trace_id = %self.trace_id,
plan_kind = self.plan_kind,
request_id = %short_request_id(last_plan.request_id.as_str()),
candidate_id = ?last_plan.candidate_id,
provider_name = last_plan.provider_name.as_deref().unwrap_or("-"),
endpoint_id = %last_plan.endpoint_id,
key_id = %last_plan.key_id,
model_name = last_plan.model_name.as_deref().unwrap_or("-"),
"candidate loop exhausted local sync candidates"
);
2026-05-02 13:23:54 +08:00
Ok(
build_local_execution_exhaustion(self.state, &last_plan, last_report_context.as_ref())
.await,
)
}
}
pub(crate) async fn execute_stream_plan_and_reports<T>(
state: &AppState,
trace_id: &str,
decision: &GatewayControlDecision,
plan_kind: &str,
plan_and_reports: Vec<T>,
) -> Result<LocalExecutionRequestOutcome, GatewayError>
where
2026-05-02 13:23:54 +08:00
T: AiExecutionAttempt + Send + Sync + 'static,
{
let candidate_count = plan_and_reports.len();
let first_provider = plan_and_reports
.first()
2026-05-02 13:23:54 +08:00
.and_then(|item| item.execution_plan().provider_name.as_deref())
.unwrap_or("-")
.to_string();
let span = tracing::debug_span!(
"candidates",
trace_id = %trace_id,
plan_kind,
candidate_count,
);
async move {
tracing::debug!(
event_name = "candidate_loop_started",
log_type = "event",
trace_id = %trace_id,
plan_kind,
candidate_count,
first_provider = first_provider.as_str(),
"candidate loop started"
);
2026-05-02 13:23:54 +08:00
let port = StreamAttemptLoopPort {
state,
trace_id,
decision,
plan_kind,
2026-05-02 13:23:54 +08:00
};
match run_ai_attempt_loop(&port, plan_and_reports).await? {
AiAttemptLoopOutcome::Responded(response) => {
Ok(LocalExecutionRequestOutcome::responded(response))
}
AiAttemptLoopOutcome::Exhausted(exhaustion) => {
Ok(LocalExecutionRequestOutcome::Exhausted(exhaustion))
}
AiAttemptLoopOutcome::NoPath => Ok(LocalExecutionRequestOutcome::NoPath),
}
}
.instrument(span)
.await
}
2026-05-03 20:14:29 +08:00
pub(crate) async fn execute_stream_attempt_source<T, S>(
state: &AppState,
trace_id: &str,
decision: &GatewayControlDecision,
plan_kind: &str,
mut source: S,
) -> Result<LocalExecutionRequestOutcome, GatewayError>
where
T: AiExecutionAttempt + Send + Sync + 'static,
S: LocalExecutionAttemptSource<T>,
{
let span = tracing::debug_span!("candidates", trace_id = %trace_id, plan_kind);
async move {
tracing::debug!(
event_name = "candidate_loop_started",
log_type = "event",
trace_id = %trace_id,
plan_kind,
"dynamic candidate loop started"
);
let port = StreamAttemptLoopPort {
state,
trace_id,
decision,
plan_kind,
};
2026-05-22 23:57:38 +08:00
run_dynamic_attempt_loop(
&port,
&mut source,
trace_id,
plan_kind,
state
.frontdoor_runtime_guards
.local_execution_planning_timeout,
)
.await
2026-05-03 20:14:29 +08:00
}
.instrument(span)
.await
}
async fn run_dynamic_attempt_loop<Port, Source, Attempt>(
port: &Port,
source: &mut Source,
2026-05-22 23:57:38 +08:00
trace_id: &str,
plan_kind: &str,
planning_timeout: Duration,
2026-05-03 20:14:29 +08:00
) -> Result<LocalExecutionRequestOutcome, GatewayError>
where
Port: AiAttemptLoopPort<
Attempt,
Response = Response<Body>,
Exhaustion = crate::executor::LocalExecutionExhaustion,
Error = GatewayError,
>,
Source: LocalExecutionAttemptSource<Attempt>,
Attempt: AiExecutionAttempt + Send + Sync + 'static,
{
let mut last_attempted = None;
2026-05-22 23:57:38 +08:00
while let Some(attempt) =
next_execution_attempt_with_timeout(source, trace_id, plan_kind, planning_timeout).await?
{
2026-05-03 20:14:29 +08:00
last_attempted = Some((attempt.execution_plan().clone(), attempt.report_context()));
if let Some(response) = port.execute_attempt(&attempt).await? {
let remaining = source.drain_execution_attempts().await?;
port.mark_unused_attempts(remaining).await?;
return Ok(LocalExecutionRequestOutcome::responded(response));
}
}
let Some((last_plan, last_report_context)) = last_attempted else {
return Ok(LocalExecutionRequestOutcome::NoPath);
};
Ok(LocalExecutionRequestOutcome::Exhausted(
port.build_exhaustion(last_plan, last_report_context)
.await?,
))
}
2026-05-22 23:57:38 +08:00
async fn next_execution_attempt_with_timeout<Source, Attempt>(
source: &mut Source,
trace_id: &str,
plan_kind: &str,
planning_timeout: Duration,
) -> Result<Option<Attempt>, GatewayError>
where
Source: LocalExecutionAttemptSource<Attempt>,
{
match timeout(planning_timeout, source.next_execution_attempt()).await {
Ok(result) => result,
Err(_) => {
let timeout_ms = planning_timeout.as_millis() as u64;
warn!(
event_name = "local_execution_candidate_planning_timeout",
log_type = "ops",
trace_id,
plan_kind,
timeout_ms,
phase = "next_execution_attempt",
"gateway timed out while planning the next local execution candidate"
);
Err(GatewayError::LocalExecutionPlanningTimeout {
trace_id: trace_id.to_string(),
phase: "next_execution_attempt",
timeout_ms,
})
}
}
}
2026-05-02 13:23:54 +08:00
struct StreamAttemptLoopPort<'a> {
state: &'a AppState,
trace_id: &'a str,
decision: &'a GatewayControlDecision,
plan_kind: &'a str,
}
#[async_trait]
impl<T> AiAttemptLoopPort<T> for StreamAttemptLoopPort<'_>
where
T: AiExecutionAttempt + Send + Sync + 'static,
{
type Response = Response<Body>;
type Exhaustion = crate::executor::LocalExecutionExhaustion;
type Error = GatewayError;
async fn execute_attempt(&self, attempt: &T) -> Result<Option<Self::Response>, Self::Error> {
let plan = attempt.execution_plan().clone();
let report_context = attempt.report_context();
let candidate_index = parse_request_candidate_report_context(report_context.as_ref())
.and_then(|context| context.candidate_index)
.map(|value| value.to_string())
.unwrap_or_else(|| "-".to_string());
debug!(
event_name = "candidate_loop_attempt_started",
log_type = "debug",
trace_id = %self.trace_id,
plan_kind = self.plan_kind,
request_id = %short_request_id(plan.request_id.as_str()),
candidate_id = ?plan.candidate_id,
provider_name = plan.provider_name.as_deref().unwrap_or("-"),
endpoint_id = %plan.endpoint_id,
key_id = %plan.key_id,
model_name = plan.model_name.as_deref().unwrap_or("-"),
2026-05-02 13:23:54 +08:00
candidate_index = candidate_index.as_str(),
"candidate loop attempting stream execution candidate"
);
let watchdog_plan = plan.clone();
let watchdog_report_context = report_context.clone();
let execution_state = self.state.clone();
let execution_trace_id = self.trace_id.to_string();
let execution_plan_kind = self.plan_kind.to_string();
let execution_decision = self.decision.clone();
let execution_report_kind = attempt.report_kind();
let mut response = execute_stream_candidate_with_watchdog(
2026-05-02 13:23:54 +08:00
self.state,
self.trace_id,
self.plan_kind,
&watchdog_plan,
watchdog_report_context.as_ref(),
move || async move {
execute_execution_runtime_stream(
&execution_state,
plan,
execution_trace_id.as_str(),
&execution_decision,
execution_plan_kind.as_str(),
execution_report_kind,
report_context,
)
.await
},
)
.await?;
if let Some(response) = response.as_mut() {
attach_redaction_execution_candidate(response, watchdog_plan.candidate_id.as_deref());
}
Ok(response)
2026-05-02 13:23:54 +08:00
}
async fn mark_unused_attempts(&self, attempts: Vec<T>) -> Result<(), Self::Error> {
mark_unused_local_candidates(self.state, attempts).await;
Ok(())
}
async fn build_exhaustion(
&self,
last_plan: aether_contracts::ExecutionPlan,
last_report_context: Option<serde_json::Value>,
) -> Result<Self::Exhaustion, Self::Error> {
warn!(
event_name = "candidate_loop_exhausted",
log_type = "ops",
trace_id = %self.trace_id,
plan_kind = self.plan_kind,
request_id = %short_request_id(last_plan.request_id.as_str()),
candidate_id = ?last_plan.candidate_id,
provider_name = last_plan.provider_name.as_deref().unwrap_or("-"),
endpoint_id = %last_plan.endpoint_id,
key_id = %last_plan.key_id,
model_name = last_plan.model_name.as_deref().unwrap_or("-"),
"candidate loop exhausted local stream candidates"
);
2026-05-02 13:23:54 +08:00
Ok(
build_local_execution_exhaustion(self.state, &last_plan, last_report_context.as_ref())
.await,
)
}
}
pub(crate) async fn mark_unused_local_candidates<T>(state: &AppState, remaining: Vec<T>)
where
2026-05-02 13:23:54 +08:00
T: AiExecutionAttempt,
{
for plan_and_report in remaining {
let report_context = plan_and_report.report_context();
2026-05-11 00:12:05 +08:00
let metadata =
local_execution_candidate_metadata_from_report_context(report_context.as_ref());
if let Some(lease) = metadata.pool_key_lease.as_ref() {
if let Err(err) =
release_admin_provider_pool_key_lease(state.runtime_state.as_ref(), lease).await
{
warn!(
error = ?err,
"gateway candidate loop: failed to release unused pool key lease"
);
}
}
if should_skip_unused_persistence_from_metadata(&metadata) {
continue;
}
record_local_request_candidate_status(
state,
2026-05-02 13:23:54 +08:00
plan_and_report.execution_plan(),
report_context.as_ref(),
SchedulerRequestCandidateStatusUpdate {
status: RequestCandidateStatus::Unused,
status_code: None,
error_type: None,
error_message: None,
latency_ms: None,
started_at_unix_ms: None,
finished_at_unix_ms: None,
},
)
.await;
}
}
fn should_skip_unused_persistence(report_context: Option<&serde_json::Value>) -> bool {
let metadata = local_execution_candidate_metadata_from_report_context(report_context);
2026-05-11 00:12:05 +08:00
should_skip_unused_persistence_from_metadata(&metadata)
}
fn should_skip_unused_persistence_from_metadata(
metadata: &crate::orchestration::LocalExecutionCandidateMetadata,
) -> bool {
2026-05-03 20:14:29 +08:00
metadata.candidate_group_id.is_some() && metadata.pool_key_index.is_some()
}
fn resolve_stream_candidate_watchdog_timeout(
plan: &aether_contracts::ExecutionPlan,
report_context: Option<&serde_json::Value>,
) -> Duration {
let upstream_is_stream = report_context
.and_then(|context| context.get(UPSTREAM_IS_STREAM_KEY))
.and_then(serde_json::Value::as_bool)
.unwrap_or(true);
2026-05-25 20:09:37 +08:00
let timeout_ms = if upstream_is_stream {
plan.timeouts
.as_ref()
.and_then(|timeouts| timeouts.first_byte_ms)
.unwrap_or(DEFAULT_STREAM_FIRST_BYTE_WATCHDOG_TIMEOUT_MS)
} else {
plan.timeouts
.as_ref()
.and_then(|timeouts| timeouts.total_ms)
.unwrap_or(DEFAULT_NON_STREAM_CANDIDATE_WATCHDOG_TIMEOUT_MS)
}
.max(1);
Duration::from_millis(timeout_ms)
}
async fn execute_stream_candidate_with_watchdog<Fut>(
state: &(impl RequestCandidateRuntimeWriter + ?Sized),
trace_id: &str,
plan_kind: &str,
plan: &aether_contracts::ExecutionPlan,
report_context: Option<&serde_json::Value>,
execute: impl FnOnce() -> Fut,
) -> Result<Option<Response<Body>>, GatewayError>
where
Fut:
std::future::Future<Output = Result<Option<Response<Body>>, GatewayError>> + Send + 'static,
{
let timeout_duration = resolve_stream_candidate_watchdog_timeout(plan, report_context);
let candidate_started_unix_ms = current_unix_ms();
let mut join_handle = tokio::spawn(execute());
match timeout(timeout_duration, &mut join_handle).await {
Ok(Ok(result)) => result,
Ok(Err(join_error)) => Err(GatewayError::Internal(format!(
"local stream candidate task join failed: {join_error}"
))),
Err(_) => {
join_handle.abort();
let finished_at_unix_ms = current_unix_ms();
let request_id = short_request_id(plan.request_id.as_str());
let provider_name = plan.provider_name.as_deref().unwrap_or("-");
let model_name = plan.model_name.as_deref().unwrap_or("-");
let candidate_index = parse_request_candidate_report_context(report_context)
.and_then(|context| context.candidate_index)
.map(|value| value.to_string())
.unwrap_or_else(|| "-".to_string());
let timeout_ms = u64::try_from(timeout_duration.as_millis()).unwrap_or(u64::MAX);
record_local_request_candidate_status(
state,
plan,
report_context,
SchedulerRequestCandidateStatusUpdate {
status: RequestCandidateStatus::Failed,
status_code: Some(http::StatusCode::GATEWAY_TIMEOUT.as_u16()),
error_type: Some("local_stream_candidate_watchdog_timeout".to_string()),
error_message: Some(format!(
"local stream candidate attempt exceeded watchdog timeout of {timeout_ms}ms"
)),
latency_ms: None,
started_at_unix_ms: Some(candidate_started_unix_ms),
finished_at_unix_ms: Some(finished_at_unix_ms),
},
)
.await;
warn!(
event_name = "local_stream_candidate_watchdog_timed_out",
log_type = "event",
trace_id = %trace_id,
plan_kind,
request_id = %request_id,
candidate_id = ?plan.candidate_id,
provider_name,
endpoint_id = %plan.endpoint_id,
key_id = %plan.key_id,
model_name,
candidate_index = candidate_index.as_str(),
timeout_ms,
"gateway local stream candidate watchdog timed out"
);
Ok(None)
}
}
}
pub(crate) async fn mark_unused_local_candidate_items<T, FPlan, FContext>(
state: &AppState,
remaining: Vec<T>,
plan: FPlan,
report_context: FContext,
) where
FPlan: Fn(&T) -> &aether_contracts::ExecutionPlan,
FContext: Fn(&T) -> Option<&serde_json::Value>,
{
for item in remaining {
let report_context = report_context(&item);
if should_skip_unused_persistence(report_context) {
continue;
}
record_local_request_candidate_status(
state,
plan(&item),
report_context,
SchedulerRequestCandidateStatusUpdate {
status: RequestCandidateStatus::Unused,
status_code: None,
error_type: None,
error_message: None,
latency_ms: None,
started_at_unix_ms: None,
finished_at_unix_ms: None,
},
)
.await;
}
}
#[cfg(test)]
mod tests {
use std::sync::Arc;
use aether_contracts::{ExecutionPlan, ExecutionTimeouts, RequestBody};
use aether_data_contracts::repository::candidates::{
RequestCandidateStatus, UpsertRequestCandidateRecord,
};
use async_trait::async_trait;
use serde_json::json;
use tokio::sync::Mutex;
use super::*;
#[derive(Debug, Default)]
struct TestRequestCandidateWriter {
records: Mutex<Vec<UpsertRequestCandidateRecord>>,
}
#[async_trait]
impl RequestCandidateRuntimeWriter for TestRequestCandidateWriter {
fn has_request_candidate_data_writer(&self) -> bool {
true
}
async fn upsert_request_candidate(
&self,
candidate: UpsertRequestCandidateRecord,
) -> Result<
Option<aether_data_contracts::repository::candidates::StoredRequestCandidate>,
GatewayError,
> {
self.records.lock().await.push(candidate);
Ok(None)
}
}
2026-05-22 23:57:38 +08:00
struct PendingAttemptSource;
#[async_trait]
impl LocalExecutionAttemptSource<()> for PendingAttemptSource {
async fn next_execution_attempt(&mut self) -> Result<Option<()>, GatewayError> {
std::future::pending::<()>().await;
Ok(None)
}
async fn drain_execution_attempts(&mut self) -> Result<Vec<()>, GatewayError> {
Ok(Vec::new())
}
}
fn test_plan(timeouts: Option<ExecutionTimeouts>) -> ExecutionPlan {
ExecutionPlan {
request_id: "req_watchdog".to_string(),
candidate_id: Some("cand_watchdog".to_string()),
provider_name: Some("provider".to_string()),
provider_id: "provider_id".to_string(),
endpoint_id: "endpoint_id".to_string(),
key_id: "key_id".to_string(),
method: "POST".to_string(),
url: "https://example.com/v1/messages".to_string(),
headers: Default::default(),
content_type: Some("application/json".to_string()),
content_encoding: None,
body: RequestBody::from_json(json!({"model": "gpt-test"})),
stream: true,
2026-04-29 09:25:19 +08:00
client_api_format: "claude:messages".to_string(),
provider_api_format: "openai:chat".to_string(),
model_name: Some("gpt-test".to_string()),
proxy: None,
2026-05-05 22:21:23 +08:00
transport_profile: None,
timeouts,
}
}
2026-05-22 23:57:38 +08:00
#[tokio::test]
async fn next_execution_attempt_times_out_instead_of_waiting_forever() {
let mut source = PendingAttemptSource;
let err = next_execution_attempt_with_timeout(
&mut source,
"trace-planning-timeout",
"openai_responses_sync",
Duration::from_millis(5),
)
.await
.expect_err("pending candidate planning should time out");
match err {
GatewayError::LocalExecutionPlanningTimeout {
trace_id,
phase,
timeout_ms,
} => {
assert_eq!(trace_id, "trace-planning-timeout");
assert_eq!(phase, "next_execution_attempt");
assert_eq!(timeout_ms, 5);
}
other => panic!("unexpected error: {other:?}"),
}
}
fn test_report_context() -> serde_json::Value {
json!({
"request_id": "req_watchdog",
"candidate_id": "cand_watchdog",
"candidate_index": 2,
"retry_index": 0,
"user_id": "user_1",
"api_key_id": "api_key_1",
})
}
#[test]
fn stream_candidate_watchdog_prefers_first_byte_timeout() {
let report_context = json!({"upstream_is_stream": true});
let timeout = resolve_stream_candidate_watchdog_timeout(
&test_plan(Some(ExecutionTimeouts {
first_byte_ms: Some(12_345),
total_ms: Some(90_000),
..ExecutionTimeouts::default()
})),
Some(&report_context),
);
assert_eq!(timeout, Duration::from_millis(12_345));
}
#[test]
fn stream_candidate_watchdog_uses_default_when_timeouts_missing() {
let timeout = resolve_stream_candidate_watchdog_timeout(&test_plan(None), None);
assert_eq!(
timeout,
2026-05-25 20:09:37 +08:00
Duration::from_millis(DEFAULT_STREAM_FIRST_BYTE_WATCHDOG_TIMEOUT_MS)
);
}
#[test]
fn stream_candidate_watchdog_ignores_total_timeout_for_stream_upstream() {
let report_context = json!({"upstream_is_stream": true});
let timeout = resolve_stream_candidate_watchdog_timeout(
&test_plan(Some(ExecutionTimeouts {
total_ms: Some(90_000),
..ExecutionTimeouts::default()
})),
Some(&report_context),
);
assert_eq!(
timeout,
Duration::from_millis(DEFAULT_STREAM_FIRST_BYTE_WATCHDOG_TIMEOUT_MS)
);
}
#[test]
fn stream_candidate_watchdog_prefers_total_timeout_when_upstream_non_stream() {
let report_context = json!({"upstream_is_stream": false});
let timeout = resolve_stream_candidate_watchdog_timeout(
&test_plan(Some(ExecutionTimeouts {
first_byte_ms: Some(300_000),
total_ms: Some(599_000),
..ExecutionTimeouts::default()
})),
Some(&report_context),
);
assert_eq!(timeout, Duration::from_millis(599_000));
}
#[test]
2026-05-25 20:09:37 +08:00
fn stream_candidate_watchdog_uses_non_stream_default_when_upstream_non_stream_lacks_total() {
let report_context = json!({"upstream_is_stream": false});
let timeout = resolve_stream_candidate_watchdog_timeout(
&test_plan(Some(ExecutionTimeouts {
2026-05-25 20:09:37 +08:00
first_byte_ms: Some(12_345),
..ExecutionTimeouts::default()
})),
Some(&report_context),
);
2026-05-25 20:09:37 +08:00
assert_eq!(
timeout,
Duration::from_millis(DEFAULT_NON_STREAM_CANDIDATE_WATCHDOG_TIMEOUT_MS)
);
}
#[test]
fn stream_candidate_watchdog_defaults_to_streaming_when_flag_missing() {
let report_context = json!({});
let timeout = resolve_stream_candidate_watchdog_timeout(
&test_plan(Some(ExecutionTimeouts {
first_byte_ms: Some(12_345),
total_ms: Some(90_000),
..ExecutionTimeouts::default()
})),
Some(&report_context),
);
assert_eq!(timeout, Duration::from_millis(12_345));
}
#[test]
fn unused_persistence_skips_pool_internal_candidates() {
assert!(should_skip_unused_persistence(Some(&json!({
2026-04-27 12:34:03 +08:00
"candidate_group_id": "pool-group",
"pool_key_index": 0,
}))));
2026-05-03 20:14:29 +08:00
assert!(should_skip_unused_persistence(Some(&json!({
"candidate_group_id": "pool-group",
"pool_key_index": 1,
}))));
assert!(!should_skip_unused_persistence(Some(&json!({
"candidate_group_id": "pool-group",
}))));
assert!(!should_skip_unused_persistence(Some(&json!({
"candidate_index": 1,
}))));
}
#[tokio::test]
async fn stream_candidate_watchdog_marks_failed_candidate_and_continues() {
let writer = Arc::new(TestRequestCandidateWriter::default());
let plan = test_plan(Some(ExecutionTimeouts {
first_byte_ms: Some(25),
..ExecutionTimeouts::default()
}));
let report_context = test_report_context();
let writer_for_task = writer.clone();
let task = tokio::spawn(async move {
execute_stream_candidate_with_watchdog(
writer_for_task.as_ref(),
"trace_watchdog",
"claude_cli_stream",
&plan,
Some(&report_context),
|| std::future::pending::<Result<Option<Response<Body>>, GatewayError>>(),
)
.await
});
tokio::time::sleep(Duration::from_millis(40)).await;
let result = task.await.expect("watchdog task should join");
assert!(matches!(result, Ok(None)));
let records = writer.records.lock().await;
assert_eq!(records.len(), 1);
let record = &records[0];
assert_eq!(record.status, RequestCandidateStatus::Failed);
assert_eq!(
record.status_code,
Some(http::StatusCode::GATEWAY_TIMEOUT.as_u16())
);
assert_eq!(
record.error_type.as_deref(),
Some("local_stream_candidate_watchdog_timeout")
);
assert!(record
.error_message
.as_deref()
.is_some_and(|message| message.contains("25ms")));
assert_eq!(record.candidate_index, 2);
}
}