@@ -23,7 +23,7 @@ use aionui_api_types::{
2323 SlashCommandCompletionBehavior , SlashCommandItem ,
2424} ;
2525use aionui_common:: {
26- AgentKillReason , AgentType , ConversationStatus , ErrorChain , TimestampMs , normalize_keys_to_snake_case,
26+ AgentKillReason , AgentType , ConversationStatus , ErrorChain , TimestampMs , normalize_keys_to_snake_case, now_ms ,
2727} ;
2828use serde_json:: Value ;
2929use std:: collections:: HashMap ;
@@ -935,6 +935,37 @@ impl AcpAgentManager {
935935 }
936936}
937937
938+ fn log_idle_acp_shutdown_started ( conversation_id : & str , backend : & str , session_id : Option < & str > , pid : u32 ) {
939+ info ! (
940+ conversation_id = %conversation_id,
941+ backend = %backend,
942+ session_id = %session_id. unwrap_or( "none" ) ,
943+ pid,
944+ reason = %"IdleTimeout" ,
945+ "Idle kill: ACP shutdown started"
946+ ) ;
947+ }
948+
949+ fn log_idle_acp_cancel_sent ( conversation_id : & str , backend : & str , session_id : & str , pid : u32 ) {
950+ info ! (
951+ conversation_id = %conversation_id,
952+ backend = %backend,
953+ session_id = %session_id,
954+ pid,
955+ "Idle kill: ACP session cancel sent"
956+ ) ;
957+ }
958+
959+ fn log_idle_acp_cancel_skipped ( conversation_id : & str , backend : & str , pid : u32 ) {
960+ info ! (
961+ conversation_id = %conversation_id,
962+ backend = %backend,
963+ pid,
964+ reason = %"no_session_id" ,
965+ "Idle kill: ACP session cancel skipped"
966+ ) ;
967+ }
968+
938969#[ async_trait:: async_trait]
939970impl crate :: agent_task:: IAgentTask for AcpAgentManager {
940971 fn agent_type ( & self ) -> AgentType {
@@ -1017,7 +1048,8 @@ impl crate::agent_task::IAgentTask for AcpAgentManager {
10171048 Ok ( ( ) )
10181049 }
10191050 Err ( err) => {
1020- let send_error = err. to_agent_send_error ( ) ;
1051+ let backend = self . params . metadata . backend . as_deref ( ) ;
1052+ let send_error = err. to_agent_send_error_for_backend ( backend) ;
10211053 let agent_err = err. into_agent_error ( ) ;
10221054 // Build a CloseReason that captures whatever context we still
10231055 // have. Two cases matter:
@@ -1082,34 +1114,65 @@ impl crate::agent_task::IAgentTask for AcpAgentManager {
10821114 // Mark closing to prevent reconnect attempts
10831115 self . permission_router . set_closing ( ) ;
10841116
1085- // Cancel the current session if active
1086- if let Ok ( session) = self . session . try_read ( )
1087- && let Some ( sid) = session. session_id ( )
1088- {
1117+ let backend = self . params . metadata . backend . as_deref ( ) . unwrap_or ( "unknown" ) ;
1118+ let pid = self . process . pid ( ) ;
1119+ let idle_timeout = matches ! ( reason, Some ( AgentKillReason :: IdleTimeout ) ) ;
1120+ let session_id = self
1121+ . session
1122+ . try_read ( )
1123+ . ok ( )
1124+ . and_then ( |session| session. session_id ( ) . map ( ToOwned :: to_owned) ) ;
1125+
1126+ if idle_timeout {
1127+ log_idle_acp_shutdown_started ( & self . params . conversation_id , backend, session_id. as_deref ( ) , pid) ;
1128+ }
1129+
1130+ if let Some ( sid) = session_id. as_deref ( ) {
10891131 self . protocol . cancel ( CancelNotification :: new ( SessionId :: new ( sid) ) ) ;
1132+ if idle_timeout {
1133+ log_idle_acp_cancel_sent ( & self . params . conversation_id , backend, sid, pid) ;
1134+ }
1135+ } else if idle_timeout {
1136+ log_idle_acp_cancel_skipped ( & self . params . conversation_id , backend, pid) ;
10901137 }
10911138
10921139 let process = Arc :: clone ( & self . process ) ;
10931140 let grace = Duration :: from_millis ( ACP_KILL_GRACE_MS ) ;
10941141 let conversation_id = self . params . conversation_id . clone ( ) ;
1095- let pid = process. pid ( ) ;
1142+ let process_group_id = process. process_group_id ( ) ;
1143+ let backend = backend. to_owned ( ) ;
1144+ let idle_timeout = matches ! ( reason, Some ( AgentKillReason :: IdleTimeout ) ) ;
10961145
10971146 tokio:: spawn ( async move {
1098- if let Err ( e) = process. kill ( grace) . await {
1099- // Tag the failure with conversation_id + pid so Sentry can
1100- // group these and ops can correlate with the matching
1101- // "Killing ACP agent" log line. ELECTRON-1E9: an unannotated
1102- // failure here on Windows left the CLI subprocess running
1103- // while the manager believed it had been torn down,
1104- // producing the "no reply / second send hangs" symptom.
1105- error ! (
1106- %conversation_id,
1107- pid,
1108- error = %ErrorChain ( & e) ,
1109- "Failed to kill ACP process"
1110- ) ;
1111- } else {
1112- debug ! ( %conversation_id, pid, "ACP process kill completed" ) ;
1147+ let started_at = now_ms ( ) ;
1148+ match process. kill ( grace) . await {
1149+ Ok ( ( ) ) => {
1150+ if idle_timeout {
1151+ info ! (
1152+ %conversation_id,
1153+ backend,
1154+ pid,
1155+ process_group_id,
1156+ elapsed_ms = now_ms( ) . saturating_sub( started_at) ,
1157+ result = "ok" ,
1158+ "Idle kill: ACP process shutdown completed"
1159+ ) ;
1160+ } else {
1161+ debug ! ( %conversation_id, pid, process_group_id, "ACP process kill completed" ) ;
1162+ }
1163+ }
1164+ Err ( e) => {
1165+ error ! (
1166+ %conversation_id,
1167+ backend,
1168+ pid,
1169+ process_group_id,
1170+ elapsed_ms = now_ms( ) . saturating_sub( started_at) ,
1171+ result = "error" ,
1172+ error = %ErrorChain ( & e) ,
1173+ "Idle kill: ACP process shutdown completed"
1174+ ) ;
1175+ }
11131176 }
11141177 } ) ;
11151178
@@ -1189,6 +1252,42 @@ mod tests {
11891252 use serde_json:: json;
11901253 use std:: collections:: HashMap ;
11911254
1255+ fn capture_logs ( max_level : tracing:: Level , f : impl FnOnce ( ) ) -> String {
1256+ use std:: io:: Write ;
1257+ use std:: sync:: { Arc , Mutex } ;
1258+ use tracing_subscriber:: fmt;
1259+
1260+ #[ derive( Clone ) ]
1261+ struct SharedBuf ( Arc < Mutex < Vec < u8 > > > ) ;
1262+
1263+ impl Write for SharedBuf {
1264+ fn write ( & mut self , buf : & [ u8 ] ) -> std:: io:: Result < usize > {
1265+ self . 0 . lock ( ) . unwrap ( ) . extend_from_slice ( buf) ;
1266+ Ok ( buf. len ( ) )
1267+ }
1268+
1269+ fn flush ( & mut self ) -> std:: io:: Result < ( ) > {
1270+ Ok ( ( ) )
1271+ }
1272+ }
1273+
1274+ let buffer = Arc :: new ( Mutex :: new ( Vec :: < u8 > :: new ( ) ) ) ;
1275+ let make_writer = {
1276+ let buffer = Arc :: clone ( & buffer) ;
1277+ move || SharedBuf ( Arc :: clone ( & buffer) )
1278+ } ;
1279+
1280+ let subscriber = fmt:: Subscriber :: builder ( )
1281+ . with_max_level ( max_level)
1282+ . with_writer ( make_writer)
1283+ . with_ansi ( false )
1284+ . finish ( ) ;
1285+
1286+ tracing:: subscriber:: with_default ( subscriber, f) ;
1287+
1288+ String :: from_utf8 ( buffer. lock ( ) . unwrap ( ) . clone ( ) ) . unwrap ( )
1289+ }
1290+
11921291 #[ test]
11931292 fn exit_status_parts_handles_missing_status ( ) {
11941293 assert_eq ! ( exit_status_parts( None ) , ( None , None ) ) ;
@@ -1225,6 +1324,33 @@ mod tests {
12251324 assert_eq ! ( user_facing_message( & err) , "Rate limited" ) ;
12261325 }
12271326
1327+ #[ test]
1328+ fn idle_acp_shutdown_started_log_contains_diagnostic_context ( ) {
1329+ let captured = capture_logs ( tracing:: Level :: INFO , || {
1330+ super :: log_idle_acp_shutdown_started ( "conv_openclaw" , "openclaw" , Some ( "session_123" ) , 4242 ) ;
1331+ } ) ;
1332+
1333+ assert ! ( captured. contains( "Idle kill: ACP shutdown started" ) ) ;
1334+ assert ! ( captured. contains( "conversation_id=conv_openclaw" ) ) ;
1335+ assert ! ( captured. contains( "backend=openclaw" ) ) ;
1336+ assert ! ( captured. contains( "session_id=session_123" ) ) ;
1337+ assert ! ( captured. contains( "pid=4242" ) ) ;
1338+ assert ! ( captured. contains( "reason=IdleTimeout" ) ) ;
1339+ }
1340+
1341+ #[ test]
1342+ fn idle_acp_cancel_skipped_log_contains_reason ( ) {
1343+ let captured = capture_logs ( tracing:: Level :: INFO , || {
1344+ super :: log_idle_acp_cancel_skipped ( "conv_openclaw" , "openclaw" , 4242 ) ;
1345+ } ) ;
1346+
1347+ assert ! ( captured. contains( "Idle kill: ACP session cancel skipped" ) ) ;
1348+ assert ! ( captured. contains( "conversation_id=conv_openclaw" ) ) ;
1349+ assert ! ( captured. contains( "backend=openclaw" ) ) ;
1350+ assert ! ( captured. contains( "pid=4242" ) ) ;
1351+ assert ! ( captured. contains( "reason=no_session_id" ) ) ;
1352+ }
1353+
12281354 #[ test]
12291355 fn warmup_does_not_mark_opened_when_protocol_disconnected_after_open ( ) {
12301356 let mut session = AcpSession :: new ( None , None , Default :: default ( ) ) ;
0 commit comments