feat(diag): instrumente les blocages de délégation idea_ask_agent
Ajoute des logs diag! sans changement sémantique le long du canal de délégation inter-agents (application/orchestrator, infrastructure input, mailbox, mcp server & tools) pour diagnostiquer les blocages récurrents de idea_ask_agent. Couvert par les tests existants étendus (mcp_server, mailbox, input, tools, orchestrator_service). Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
This commit is contained in:
@ -890,6 +890,10 @@ impl OrchestratorService {
|
||||
g.would_cycle(from, agent_id)
|
||||
};
|
||||
if cycles {
|
||||
crate::diag!(
|
||||
"[rendezvous] cycle refused: requester={from} -> target={target} \
|
||||
(agent {agent_id}) (deadlock évité, aucun enqueue)",
|
||||
);
|
||||
return Err(AppError::Invalid(format!(
|
||||
"délégation ré-entrante refusée : demander à l'agent '{target}' créerait \
|
||||
un cycle d'attente inter-agents (deadlock évité)"
|
||||
@ -905,9 +909,31 @@ impl OrchestratorService {
|
||||
// Sérialisation FIFO **par agent** (A0) : verrou de tour de la **cible**, tenu
|
||||
// pour TOUT le tour (enqueue → réponse). RAII : tombe sur chaque early-return.
|
||||
let lock = self.ask_lock_for(&agent_id);
|
||||
// Diagnostics : tracer l'attente du verrou de tour. Un « turn-lock waiting » sans
|
||||
// « turn-lock acquired » qui suit signe un tour précédent jamais relâché (la cible
|
||||
// reste Busy) — le verrou n'est libéré qu'à la fin du tour courant.
|
||||
crate::diag!(
|
||||
"[rendezvous] turn-lock waiting: requester={} -> target={target} (agent {agent_id}) \
|
||||
wait_cap_ms={}",
|
||||
requester.map_or_else(|| "user".to_owned(), |a| a.to_string()),
|
||||
ASK_QUEUE_WAIT_CAP.as_millis(),
|
||||
);
|
||||
let lock_wait = Instant::now();
|
||||
let _turn = match tokio::time::timeout(ASK_QUEUE_WAIT_CAP, lock.lock_owned()).await {
|
||||
Ok(guard) => guard,
|
||||
Ok(guard) => {
|
||||
crate::diag!(
|
||||
"[rendezvous] turn-lock acquired: target={target} (agent {agent_id}) \
|
||||
waited_ms={}",
|
||||
lock_wait.elapsed().as_millis(),
|
||||
);
|
||||
guard
|
||||
}
|
||||
Err(_elapsed) => {
|
||||
crate::diag!(
|
||||
"[rendezvous] turn-lock TIMEOUT: target={target} (agent {agent_id}) \
|
||||
waited_ms={} (tour précédent jamais relâché ?)",
|
||||
lock_wait.elapsed().as_millis(),
|
||||
);
|
||||
return Err(AppError::from(domain::ports::AgentSessionError::Timeout));
|
||||
}
|
||||
};
|
||||
@ -967,6 +993,14 @@ impl OrchestratorService {
|
||||
// des deux ⇒ pas de gate (livraison immédiate, sinon blocage indéfini).
|
||||
let gate_cold_start =
|
||||
cold_launch && (prompt_pattern.as_ref().is_some_and(|p| !p.is_empty()) || has_mcp);
|
||||
// Diagnostics : décision de gate du premier tour. `gate_cold_start=false` sur une
|
||||
// cible froide SANS signal de libération (ni prompt-ready ni MCP) livrerait
|
||||
// immédiatement ; un `true` diffère la livraison jusqu'au signal.
|
||||
crate::diag!(
|
||||
"[rendezvous] gate decision: target={target} (agent {agent_id}) cold_launch={cold_launch} \
|
||||
has_prompt_pattern={} has_mcp={has_mcp} gate_cold_start={gate_cold_start}",
|
||||
prompt_pattern.as_ref().is_some_and(|p| !p.is_empty()),
|
||||
);
|
||||
if gate_cold_start {
|
||||
input.mark_starting(agent_id);
|
||||
}
|
||||
@ -1011,8 +1045,8 @@ impl OrchestratorService {
|
||||
let started = Instant::now();
|
||||
crate::diag!(
|
||||
"[rendezvous] ask started: requester={} -> target={target} (agent {agent_id}) \
|
||||
ticket={ticket_id} cold_launch={cold_launch} gate_cold_start={gate_cold_start} \
|
||||
turn_timeout_ms={}",
|
||||
conversation={conversation_id} ticket={ticket_id} cold_launch={cold_launch} \
|
||||
gate_cold_start={gate_cold_start} turn_timeout_ms={}",
|
||||
requester.map_or_else(|| "user".to_owned(), |a| a.to_string()),
|
||||
turn_timeout.as_millis(),
|
||||
);
|
||||
@ -1155,6 +1189,18 @@ impl OrchestratorService {
|
||||
let busy_guard =
|
||||
BusyTurnGuard::new(Arc::clone(input), Arc::clone(mailbox), agent_id, ticket_id);
|
||||
|
||||
// Rendezvous beacon (chemin structuré) : équivalent du « ask started » du chemin
|
||||
// PTY. La cible n'a pas de PTY ; le tour se débloque sur le `Final` de sa session
|
||||
// OU sur un `idea_reply`. Sans l'un des deux avant `turn_timeout`, le drain expire.
|
||||
let started = Instant::now();
|
||||
crate::diag!(
|
||||
"[rendezvous] ask started (structured): requester={} -> target={target} \
|
||||
(agent {agent_id}) conversation={conversation_id} ticket={ticket_id} \
|
||||
turn_timeout_ms={}",
|
||||
requester.map_or_else(|| "user".to_owned(), |a| a.to_string()),
|
||||
turn_timeout.as_millis(),
|
||||
);
|
||||
|
||||
// Drainer le tour structuré (le `Final` ⇒ contenu + `mark_idle`), borné par le
|
||||
// **même** garde-fou que le chemin PTY (profil ou défaut). On attend la
|
||||
// **première** issue : le tour structuré OU un `idea_reply` explicite.
|
||||
@ -1165,9 +1211,24 @@ impl OrchestratorService {
|
||||
biased;
|
||||
// Issue déterministe : la session a rendu son `Final`.
|
||||
drained = drain => match drained {
|
||||
Ok(content) => content,
|
||||
Ok(content) => {
|
||||
crate::diag!(
|
||||
"[rendezvous] ask resolved (structured/final): target={target} \
|
||||
(agent {agent_id}) ticket={ticket_id} after_ms={} reply_len={}",
|
||||
started.elapsed().as_millis(),
|
||||
content.len(),
|
||||
);
|
||||
content
|
||||
}
|
||||
// Erreur de drain : le garde fait `cancel_head` + `mark_idle` au Drop.
|
||||
Err(err) => return Err(AppError::from(err)),
|
||||
Err(err) => {
|
||||
crate::diag!(
|
||||
"[rendezvous] ask drain-error (structured): target={target} \
|
||||
(agent {agent_id}) ticket={ticket_id} after_ms={} err={err}",
|
||||
started.elapsed().as_millis(),
|
||||
);
|
||||
return Err(AppError::from(err));
|
||||
}
|
||||
},
|
||||
// Issue alternative : un `idea_reply` explicite a résolu le ticket d'abord.
|
||||
replied = pending => match replied {
|
||||
@ -1175,10 +1236,21 @@ impl OrchestratorService {
|
||||
// La session draine encore en arrière-plan ; on s'assure que la FIFO
|
||||
// avance même si le `Final` n'est pas encore observé.
|
||||
input.mark_idle(agent_id);
|
||||
crate::diag!(
|
||||
"[rendezvous] ask resolved (structured/reply): target={target} \
|
||||
(agent {agent_id}) ticket={ticket_id} after_ms={} reply_len={}",
|
||||
started.elapsed().as_millis(),
|
||||
content.len(),
|
||||
);
|
||||
content
|
||||
}
|
||||
// Canal fermé : le garde fait `cancel_head` + `mark_idle` au Drop.
|
||||
Err(_cancelled) => {
|
||||
crate::diag!(
|
||||
"[rendezvous] ask channel-closed (structured): target={target} \
|
||||
(agent {agent_id}) ticket={ticket_id} after_ms={}",
|
||||
started.elapsed().as_millis(),
|
||||
);
|
||||
return Err(AppError::Process(format!(
|
||||
"agent {target} : canal de réponse fermé avant un résultat"
|
||||
)));
|
||||
@ -1413,7 +1485,18 @@ impl OrchestratorService {
|
||||
ticket: Option<TicketId>,
|
||||
result: String,
|
||||
) -> Result<OrchestratorOutcome, AppError> {
|
||||
// Diagnostics : un `idea_reply` est entré, AVANT toute corrélation. Longueur
|
||||
// seulement (jamais le corps). Si ce beacon apparaît mais que `correlated`/
|
||||
// `UNMATCHED` ne suit pas, la file n'est pas câblée.
|
||||
crate::diag!(
|
||||
"[rendezvous] idea_reply received: from agent {from} ticket={} result_len={}",
|
||||
ticket.map_or_else(|| "head".to_owned(), |t| t.to_string()),
|
||||
result.len(),
|
||||
);
|
||||
let mailbox = self.mailbox.as_ref().ok_or_else(|| {
|
||||
crate::diag!(
|
||||
"[rendezvous] idea_reply DROPPED: from agent {from} (file inter-agents non câblée)",
|
||||
);
|
||||
AppError::Invalid(
|
||||
"idea_reply n'est pas disponible : file inter-agents non câblée".to_owned(),
|
||||
)
|
||||
|
||||
Reference in New Issue
Block a user