From fa1d1ea653a49ce85953d18e50ff64fe2c73cfba Mon Sep 17 00:00:00 2001 From: David Abram Date: Thu, 13 Aug 2026 13:46:54 +0200 Subject: [PATCH 1/2] trace: Improve sync progress and resilience Add injectable text-mode progress events and UTC lifecycle timestamps, routing human feedback to stderr while preserving the final stdout and JSON contracts. Reduce export batches to 100 rows and make ingestion-state requests use one 60-second attempt. Update the trace-sync plans, decision record, and related CLI context documentation. Plan: trace-sync-progress\nTask: T01, T02, T03, T04\nPlan: agent-trace-sync-state-timeout\nTask: T01 Co-authored-by: SCE --- cli/src/app.rs | 17 +- cli/src/services/agent_trace_export/mod.rs | 62 +-- .../agent_trace_sync/control_plane.rs | 23 +- cli/src/services/app_support.rs | 6 +- cli/src/services/command_registry.rs | 17 +- cli/src/services/trace/command.rs | 138 +++++- cli/src/services/trace/sync.rs | 404 +++++++++++++++++- context/architecture.md | 2 +- context/cli/agent-trace-sync-command.md | 3 +- context/cli/trace-command.md | 3 +- context/context-map.md | 3 +- ...-13-trace-sync-progress-stream-contract.md | 53 +++ context/glossary.md | 2 +- context/overview.md | 4 +- .../plans/agent-trace-sync-state-timeout.md | 93 ++++ context/plans/trace-sync-progress.md | 126 ++++++ context/sce/agent-trace-export-readers.md | 2 +- context/sce/cli-stdout-stderr-contract.md | 3 + 18 files changed, 900 insertions(+), 61 deletions(-) create mode 100644 context/decisions/2026-08-13-trace-sync-progress-stream-contract.md create mode 100644 context/plans/agent-trace-sync-state-timeout.md create mode 100644 context/plans/trace-sync-progress.md diff --git a/cli/src/app.rs b/cli/src/app.rs index aacbe1fa..dff2b8b2 100644 --- a/cli/src/app.rs +++ b/cli/src/app.rs @@ -269,26 +269,28 @@ where StderrW: Write, { app_support::render_run_outcome( - try_run_with_dependency_check(args, dependency_check), + try_run_with_dependency_check(args, dependency_check, stderr), stdout, stderr, ) } -fn try_run_with_dependency_check( +fn try_run_with_dependency_check( args: I, dependency_check: F, + stderr: &mut StderrW, ) -> RunOutcome where I: IntoIterator, F: FnOnce() -> anyhow::Result<()>, + StderrW: Write, { let result = perform_dependency_check(dependency_check) .and_then(|()| build_startup_context()) .and_then(initialize_runtime) .map(|runtime| { let startup_diagnostic = runtime.startup_diagnostic.clone(); - let result = run_command_lifecycle(args, &runtime); + let result = run_command_lifecycle(args, &runtime, stderr); RunOutcome { logger: Some(runtime.logger), startup_diagnostic, @@ -345,9 +347,14 @@ fn initialize_runtime(startup: StartupContext) -> Result(args: I, runtime: &AppRuntime) -> Result +fn run_command_lifecycle( + args: I, + runtime: &AppRuntime, + stderr: &mut StderrW, +) -> Result where I: IntoIterator, + StderrW: Write, { let context = runtime.context(); let mut args = Some(args.into_iter().collect::>()); @@ -362,7 +369,7 @@ where return Err(ClassifiedError::runtime(REPEATED_COMMAND_DISPATCH_ERROR)); }; let command = parse_command_phase(command_args, &runtime.registry, &context)?; - app_support::execute_command_phase(&command, &context) + app_support::execute_command_phase(&command, &context, stderr) }) } diff --git a/cli/src/services/agent_trace_export/mod.rs b/cli/src/services/agent_trace_export/mod.rs index b3ee1450..626b3c8b 100644 --- a/cli/src/services/agent_trace_export/mod.rs +++ b/cli/src/services/agent_trace_export/mod.rs @@ -10,7 +10,7 @@ use serde::Serialize; use crate::services::agent_trace_db::{repository::RepositoryAgentTraceDb, MessageRole}; /// Maximum number of rows a single export reader call may return. -pub const AGENT_TRACE_EXPORT_BATCH_SIZE: usize = 500; +pub const AGENT_TRACE_EXPORT_BATCH_SIZE: usize = 100; /// Largest integer value that round-trips exactly through an IEEE-754 double /// (`Number.MAX_SAFE_INTEGER`). @@ -667,7 +667,7 @@ mod tests { let reader = AgentTraceExportReader::new(&db); let rows = reader - .read_messages_after(1, 500) + .read_messages_after(1, AGENT_TRACE_EXPORT_BATCH_SIZE) .expect("read after cursor should succeed"); assert_eq!( @@ -696,7 +696,7 @@ mod tests { let reader = AgentTraceExportReader::new(&db); let rows = reader - .read_messages_after(10, 500) + .read_messages_after(10, AGENT_TRACE_EXPORT_BATCH_SIZE) .expect("read after cursor should succeed"); assert_eq!( @@ -759,11 +759,11 @@ mod tests { let reader = AgentTraceExportReader::new(&db); assert!(reader - .read_messages_after(1, 500) + .read_messages_after(1, AGENT_TRACE_EXPORT_BATCH_SIZE) .expect("read at max id should succeed") .is_empty()); assert!(reader - .read_messages_after(100, 500) + .read_messages_after(100, AGENT_TRACE_EXPORT_BATCH_SIZE) .expect("read beyond max id should succeed") .is_empty()); @@ -777,7 +777,7 @@ mod tests { let reader = AgentTraceExportReader::new(&db); let cursor_error = reader - .read_messages_after(-1, 500) + .read_messages_after(-1, AGENT_TRACE_EXPORT_BATCH_SIZE) .expect_err("negative cursor should error"); assert!(cursor_error.to_string().contains("cursor")); @@ -806,7 +806,7 @@ mod tests { let reader = AgentTraceExportReader::new(&db); let error = reader - .read_messages_after(0, 500) + .read_messages_after(0, AGENT_TRACE_EXPORT_BATCH_SIZE) .expect_err("row above safe-integer bound should error"); assert!(error.to_string().contains("JS-safe-integer")); @@ -825,7 +825,7 @@ mod tests { let reader = AgentTraceExportReader::new(&db); reader - .read_messages_after(0, 500) + .read_messages_after(0, AGENT_TRACE_EXPORT_BATCH_SIZE) .expect("read should succeed"); assert_eq!(row_count(&db, "messages"), messages_before); @@ -858,7 +858,7 @@ mod tests { let reader = AgentTraceExportReader::new(&db); let rows = reader - .read_parts_after(0, 500) + .read_parts_after(0, AGENT_TRACE_EXPORT_BATCH_SIZE) .expect("read after cursor should succeed"); assert_eq!( @@ -888,7 +888,7 @@ mod tests { let reader = AgentTraceExportReader::new(&db); let rows = reader - .read_parts_after(10, 500) + .read_parts_after(10, AGENT_TRACE_EXPORT_BATCH_SIZE) .expect("read after cursor should succeed"); assert_eq!( @@ -945,11 +945,11 @@ mod tests { let reader = AgentTraceExportReader::new(&db); assert!(reader - .read_parts_after(1, 500) + .read_parts_after(1, AGENT_TRACE_EXPORT_BATCH_SIZE) .expect("read at max id should succeed") .is_empty()); assert!(reader - .read_parts_after(100, 500) + .read_parts_after(100, AGENT_TRACE_EXPORT_BATCH_SIZE) .expect("read beyond max id should succeed") .is_empty()); @@ -963,7 +963,7 @@ mod tests { let reader = AgentTraceExportReader::new(&db); let cursor_error = reader - .read_parts_after(-1, 500) + .read_parts_after(-1, AGENT_TRACE_EXPORT_BATCH_SIZE) .expect_err("negative cursor should error"); assert!(cursor_error.to_string().contains("cursor")); @@ -992,7 +992,7 @@ mod tests { let reader = AgentTraceExportReader::new(&db); let error = reader - .read_parts_after(0, 500) + .read_parts_after(0, AGENT_TRACE_EXPORT_BATCH_SIZE) .expect_err("row above safe-integer bound should error"); assert!(error.to_string().contains("JS-safe-integer")); @@ -1011,7 +1011,7 @@ mod tests { let reader = AgentTraceExportReader::new(&db); reader - .read_parts_after(0, 500) + .read_parts_after(0, AGENT_TRACE_EXPORT_BATCH_SIZE) .expect("read should succeed"); assert_eq!(row_count(&db, "parts"), parts_before); @@ -1047,7 +1047,7 @@ mod tests { let reader = AgentTraceExportReader::new(&db); let rows = reader - .read_diff_traces_after(1, 500) + .read_diff_traces_after(1, AGENT_TRACE_EXPORT_BATCH_SIZE) .expect("read after cursor should succeed"); assert_eq!( @@ -1081,7 +1081,7 @@ mod tests { let reader = AgentTraceExportReader::new(&db); let rows = reader - .read_diff_traces_after(0, 500) + .read_diff_traces_after(0, AGENT_TRACE_EXPORT_BATCH_SIZE) .expect("read after cursor should succeed"); assert_eq!(rows.len(), 1); @@ -1111,7 +1111,7 @@ mod tests { let reader = AgentTraceExportReader::new(&db); let rows = reader - .read_diff_traces_after(10, 500) + .read_diff_traces_after(10, AGENT_TRACE_EXPORT_BATCH_SIZE) .expect("read after cursor should succeed"); assert_eq!( @@ -1168,11 +1168,11 @@ mod tests { let reader = AgentTraceExportReader::new(&db); assert!(reader - .read_diff_traces_after(1, 500) + .read_diff_traces_after(1, AGENT_TRACE_EXPORT_BATCH_SIZE) .expect("read at max id should succeed") .is_empty()); assert!(reader - .read_diff_traces_after(100, 500) + .read_diff_traces_after(100, AGENT_TRACE_EXPORT_BATCH_SIZE) .expect("read beyond max id should succeed") .is_empty()); @@ -1186,7 +1186,7 @@ mod tests { let reader = AgentTraceExportReader::new(&db); let cursor_error = reader - .read_diff_traces_after(-1, 500) + .read_diff_traces_after(-1, AGENT_TRACE_EXPORT_BATCH_SIZE) .expect_err("negative cursor should error"); assert!(cursor_error.to_string().contains("cursor")); @@ -1224,7 +1224,7 @@ mod tests { let reader = AgentTraceExportReader::new(&db); let error = reader - .read_diff_traces_after(0, 500) + .read_diff_traces_after(0, AGENT_TRACE_EXPORT_BATCH_SIZE) .expect_err("row above safe-integer bound should error"); assert!(error.to_string().contains("JS-safe-integer")); @@ -1243,7 +1243,7 @@ mod tests { let reader = AgentTraceExportReader::new(&db); reader - .read_diff_traces_after(0, 500) + .read_diff_traces_after(0, AGENT_TRACE_EXPORT_BATCH_SIZE) .expect("read should succeed"); assert_eq!(row_count(&db, "diff_traces"), diff_traces_before); @@ -1277,7 +1277,7 @@ mod tests { let reader = AgentTraceExportReader::new(&db); let rows = reader - .read_agent_traces_after(1, 500) + .read_agent_traces_after(1, AGENT_TRACE_EXPORT_BATCH_SIZE) .expect("read after cursor should succeed"); assert_eq!( @@ -1305,7 +1305,7 @@ mod tests { let reader = AgentTraceExportReader::new(&db); let rows = reader - .read_agent_traces_after(0, 500) + .read_agent_traces_after(0, AGENT_TRACE_EXPORT_BATCH_SIZE) .expect("read after cursor should succeed"); assert_eq!(rows.len(), 1); @@ -1329,7 +1329,7 @@ mod tests { let reader = AgentTraceExportReader::new(&db); let rows = reader - .read_agent_traces_after(10, 500) + .read_agent_traces_after(10, AGENT_TRACE_EXPORT_BATCH_SIZE) .expect("read after cursor should succeed"); assert_eq!( @@ -1386,11 +1386,11 @@ mod tests { let reader = AgentTraceExportReader::new(&db); assert!(reader - .read_agent_traces_after(1, 500) + .read_agent_traces_after(1, AGENT_TRACE_EXPORT_BATCH_SIZE) .expect("read at max id should succeed") .is_empty()); assert!(reader - .read_agent_traces_after(100, 500) + .read_agent_traces_after(100, AGENT_TRACE_EXPORT_BATCH_SIZE) .expect("read beyond max id should succeed") .is_empty()); @@ -1404,7 +1404,7 @@ mod tests { let reader = AgentTraceExportReader::new(&db); let cursor_error = reader - .read_agent_traces_after(-1, 500) + .read_agent_traces_after(-1, AGENT_TRACE_EXPORT_BATCH_SIZE) .expect_err("negative cursor should error"); assert!(cursor_error.to_string().contains("cursor")); @@ -1441,7 +1441,7 @@ mod tests { let reader = AgentTraceExportReader::new(&db); let error = reader - .read_agent_traces_after(0, 500) + .read_agent_traces_after(0, AGENT_TRACE_EXPORT_BATCH_SIZE) .expect_err("row above safe-integer bound should error"); assert!(error.to_string().contains("JS-safe-integer")); @@ -1460,7 +1460,7 @@ mod tests { let reader = AgentTraceExportReader::new(&db); reader - .read_agent_traces_after(0, 500) + .read_agent_traces_after(0, AGENT_TRACE_EXPORT_BATCH_SIZE) .expect("read should succeed"); assert_eq!(row_count(&db, "agent_traces"), agent_traces_before); diff --git a/cli/src/services/agent_trace_sync/control_plane.rs b/cli/src/services/agent_trace_sync/control_plane.rs index 362131ab..4c91f0c1 100644 --- a/cli/src/services/agent_trace_sync/control_plane.rs +++ b/cli/src/services/agent_trace_sync/control_plane.rs @@ -106,8 +106,8 @@ pub struct AgentTraceIngestionBatchResponse { const STATE_PATH: &str = "agent-trace/ingestion/state"; const BATCH_PATH: &str = "agent-trace/ingestion/batch"; -const STATE_RETRY_MAX_ATTEMPTS: u32 = 3; -const STATE_RETRY_TIMEOUT_MS: u64 = 10_000; +const STATE_RETRY_MAX_ATTEMPTS: u32 = 1; +const STATE_RETRY_TIMEOUT_MS: u64 = 60_000; const STATE_RETRY_INITIAL_BACKOFF_MS: u64 = 250; const STATE_RETRY_MAX_BACKOFF_MS: u64 = 2_000; @@ -265,9 +265,9 @@ impl AuthenticatedControlPlaneClient { } } - /// Calls `POST /agent-trace/ingestion/state`, retrying transient - /// `500`/`503`/transport failures via the existing sync resilience retry - /// policy. `400`/`403`/post-refresh-`401` are terminal and never retried. + /// Calls `POST /agent-trace/ingestion/state` with a single attempt and a + /// 60-second timeout. `400`/`403`/post-refresh-`401` are terminal and never + /// retried. pub async fn ingestion_state( &self, request: &AgentTraceIngestionStateRequest, @@ -998,6 +998,19 @@ mod tests { ); } + #[test] + fn transient_state_failure_fails_after_one_http_attempt() { + let server = TestHttpServer::start(); + server.queue_response(CannedResponse::json(503, &json!({"error": "unavailable"}))); + let store = FakeCredentialStore::with_tokens(valid_stored_tokens("valid-access-token")); + let client = client_with(&server, store); + + let error = block_on(client.ingestion_state(&sample_state_request())).unwrap_err(); + + assert!(matches!(error, ControlPlaneError::ServerError(_))); + assert_eq!(server.call_count(), 1); + } + #[test] fn valid_token_is_not_resaved() { let server = TestHttpServer::start(); diff --git a/cli/src/services/app_support.rs b/cli/src/services/app_support.rs index fa5eef73..cf9c2087 100644 --- a/cli/src/services/app_support.rs +++ b/cli/src/services/app_support.rs @@ -101,12 +101,14 @@ pub(crate) fn log_startup_configuration( } } -pub(crate) fn execute_command_phase( +pub(crate) fn execute_command_phase( command: &RuntimeCommand, context: &C, + stderr: &mut W, ) -> Result where C: HasLogger + ContextWithRepoRoot, + W: Write, { let command_name = command.name(); let logger = context.logger(); @@ -116,7 +118,7 @@ where &[("command", command_name.as_ref())], None, ); - let dispatch_result = command.execute(context); + let dispatch_result = command.execute_with_stderr(context, stderr); if dispatch_result.is_ok() { logger.debug( "sce.command.dispatch_end", diff --git a/cli/src/services/command_registry.rs b/cli/src/services/command_registry.rs index d1f4e945..cc4675ac 100644 --- a/cli/src/services/command_registry.rs +++ b/cli/src/services/command_registry.rs @@ -1,4 +1,5 @@ use std::borrow::Cow; +use std::io::Write; use crate::app::{ContextWithRepoRoot, HasLogger}; use crate::services; @@ -53,9 +54,23 @@ impl RuntimeCommand { } } + #[allow(dead_code)] pub fn execute(&self, context: &C) -> Result where C: HasLogger + ContextWithRepoRoot, + { + let mut stderr = std::io::sink(); + self.execute_with_stderr(context, &mut stderr) + } + + pub fn execute_with_stderr( + &self, + context: &C, + stderr: &mut W, + ) -> Result + where + C: HasLogger + ContextWithRepoRoot, + W: Write, { match self { Self::Help(_) => Ok(services::help::help_text()), @@ -68,7 +83,7 @@ impl RuntimeCommand { Self::Policy(command) => command.execute(), Self::Version(command) => command.execute(context), Self::Completion(command) => Ok(command.execute(context)), - Self::Trace(command) => command.execute(context), + Self::Trace(command) => command.execute_with_stderr(context, stderr), } } } diff --git a/cli/src/services/trace/command.rs b/cli/src/services/trace/command.rs index ef0aa378..97e207d7 100644 --- a/cli/src/services/trace/command.rs +++ b/cli/src/services/trace/command.rs @@ -1,3 +1,5 @@ +use std::io::Write; + use crate::app::ContextWithRepoRoot; use crate::services::error::ClassifiedError; use crate::services::trace::discovery::discover_agent_trace_dbs; @@ -8,7 +10,10 @@ use crate::services::trace::render_sync; use crate::services::trace::shell::{run_agent_trace_db_shell, ShellTarget}; use crate::services::trace::status::{resolve_current_status, StatusErrorOrRuntime}; use crate::services::trace::status_all::aggregate_current_status_all; -use crate::services::trace::sync::{run_current_sync, TraceSyncError}; +use crate::services::trace::sync::{ + run_current_sync_with_progress_and_clock, NoopSyncProgressSink, SyncProgressClock, + SyncProgressEvent, SyncProgressSink, SystemSyncProgressClock, TraceSyncError, +}; use crate::services::trace::{ resolve_agent_trace_db_identifier, TraceRequest, TraceSubcommandRequest, }; @@ -43,10 +48,94 @@ fn classify_sync_error(err: TraceSyncError) -> ClassifiedError { ClassifiedError::runtime(format!("{err}")) } +struct StderrSyncProgressReporter<'a, W> { + writer: &'a mut W, +} + +impl<'a, W> StderrSyncProgressReporter<'a, W> { + fn new(writer: &'a mut W) -> Self { + Self { writer } + } +} + +impl SyncProgressSink for StderrSyncProgressReporter<'_, W> +where + W: Write, +{ + fn report(&mut self, event: SyncProgressEvent) { + let _ = writeln!(self.writer, "{}", format_progress_event(&event)); + let _ = self.writer.flush(); + } +} + +fn format_progress_event(event: &SyncProgressEvent) -> String { + match event { + SyncProgressEvent::Started { timestamp } => { + format!("Starting Agent Trace sync at {timestamp}...") + } + SyncProgressEvent::BatchAccepted { + stream, + batch_rows, + uploaded, + cursor, + } => format!( + "{stream}: uploaded batch of {batch_rows} rows ({uploaded} total, cursor {cursor})" + ), + SyncProgressEvent::StreamCompleted { + stream, + uploaded, + cursor, + batches, + } if *batches == 0 => { + format!("{stream}: complete - no new rows uploaded (cursor {cursor})") + } + SyncProgressEvent::StreamCompleted { + stream, + uploaded, + cursor, + batches, + } => format!( + "{stream}: complete - {uploaded} rows uploaded in {batches} batches (cursor {cursor})" + ), + SyncProgressEvent::Finished { timestamp } => { + format!("Agent Trace sync finished at {timestamp}.") + } + } +} + impl TraceCommand { + #[allow(dead_code)] pub fn execute(&self, context: &C) -> Result where C: ContextWithRepoRoot, + { + let mut stderr = std::io::sink(); + self.execute_with_stderr(context, &mut stderr) + } + + pub fn execute_with_stderr( + &self, + context: &C, + stderr: &mut W, + ) -> Result + where + C: ContextWithRepoRoot, + W: Write, + { + let clock = SystemSyncProgressClock; + self.execute_with_stderr_and_clock(context, stderr, &clock) + } + + fn execute_with_stderr_and_clock( + &self, + context: &C, + stderr: &mut W, + clock: &Clock, + ) -> Result + where + C: ContextWithRepoRoot, + W: Write, + Clock: SyncProgressClock, { match &self.request.subcommand { TraceSubcommandRequest::DbList { format } => { @@ -104,7 +193,17 @@ impl TraceCommand { TraceSubcommandRequest::Sync { format } => { let repo_root = current_repo_root(context)?; - let report = run_current_sync(&repo_root).map_err(classify_sync_error)?; + let report = match format { + crate::services::output_format::OutputFormat::Text => { + let mut progress = StderrSyncProgressReporter::new(stderr); + run_current_sync_with_progress_and_clock(&repo_root, &mut progress, clock) + } + crate::services::output_format::OutputFormat::Json => { + let mut progress = NoopSyncProgressSink; + run_current_sync_with_progress_and_clock(&repo_root, &mut progress, clock) + } + } + .map_err(classify_sync_error)?; render_sync::render(&report, *format) .map_err(|error| ClassifiedError::runtime(format!("{error:#}"))) @@ -112,3 +211,38 @@ impl TraceCommand { } } } + +#[cfg(test)] +mod tests { + use super::*; + + #[test] + fn progress_reporter_writes_deterministic_text_lines_and_flushes_each_event() { + let mut output = Vec::new(); + let mut reporter = StderrSyncProgressReporter::new(&mut output); + + reporter.report(SyncProgressEvent::Started { + timestamp: "2026-01-02T03:04:05Z".to_string(), + }); + reporter.report(SyncProgressEvent::BatchAccepted { + stream: "messages", + batch_rows: 500, + uploaded: 500, + cursor: 500, + }); + reporter.report(SyncProgressEvent::StreamCompleted { + stream: "parts", + uploaded: 0, + cursor: 12, + batches: 0, + }); + reporter.report(SyncProgressEvent::Finished { + timestamp: "2026-01-02T03:04:06Z".to_string(), + }); + + assert_eq!( + String::from_utf8(output).expect("progress output should be UTF-8"), + "Starting Agent Trace sync at 2026-01-02T03:04:05Z...\nmessages: uploaded batch of 500 rows (500 total, cursor 500)\nparts: complete - no new rows uploaded (cursor 12)\nAgent Trace sync finished at 2026-01-02T03:04:06Z.\n" + ); + } +} diff --git a/cli/src/services/trace/sync.rs b/cli/src/services/trace/sync.rs index d62ee6d5..f84a9d13 100644 --- a/cli/src/services/trace/sync.rs +++ b/cli/src/services/trace/sync.rs @@ -13,6 +13,7 @@ use std::path::Path; use std::sync::OnceLock; use anyhow::Context; +use chrono::{DateTime, SecondsFormat, Utc}; use tokio::runtime::Runtime; use crate::services::agent_trace_db::repository::RepositoryAgentTraceDb; @@ -56,6 +57,72 @@ pub struct StreamSyncReport { pub batches: usize, } +/// Supplies timestamps for one trace-sync invocation. +pub trait SyncProgressClock { + fn now(&self) -> DateTime; +} + +/// Uses the system UTC clock for production sync invocations. +#[derive(Clone, Copy, Debug, Default)] +pub struct SystemSyncProgressClock; + +impl SyncProgressClock for SystemSyncProgressClock { + fn now(&self) -> DateTime { + Utc::now() + } +} + +fn timestamp(clock: &C) -> String +where + C: SyncProgressClock, +{ + clock.now().to_rfc3339_opts(SecondsFormat::AutoSi, true) +} + +/// Progress emitted while the four trace streams are synchronized. +#[derive(Clone, Debug, PartialEq, Eq)] +pub enum SyncProgressEvent { + Started { + timestamp: String, + }, + BatchAccepted { + stream: &'static str, + batch_rows: usize, + uploaded: usize, + cursor: i64, + }, + StreamCompleted { + stream: &'static str, + uploaded: usize, + cursor: i64, + batches: usize, + }, + Finished { + timestamp: String, + }, +} + +/// Receives deterministic sync progress events. +pub trait SyncProgressSink { + fn report(&mut self, event: SyncProgressEvent); +} + +impl SyncProgressSink for F +where + F: FnMut(SyncProgressEvent), +{ + fn report(&mut self, event: SyncProgressEvent) { + self(event); + } +} + +/// Discards sync progress for callers that only need the final report. +pub struct NoopSyncProgressSink; + +impl SyncProgressSink for NoopSyncProgressSink { + fn report(&mut self, _event: SyncProgressEvent) {} +} + /// Terminal failure of `sce trace sync`. #[derive(Debug)] pub enum TraceSyncError { @@ -86,7 +153,51 @@ impl std::error::Error for TraceSyncError {} /// `ContextWithRepoRoot`/`AgentTraceStorageContext`/`resolve_agent_trace_storage` /// path `sce trace status` uses) and control-plane configuration, then /// synchronizes all four capture streams. +#[allow(dead_code)] pub fn run_current_sync(repo_root: &Path) -> Result { + let mut progress = NoopSyncProgressSink; + run_current_sync_with_progress(repo_root, &mut progress) +} + +/// Production entry point with an injectable progress sink. +pub fn run_current_sync_with_progress( + repo_root: &Path, + progress: &mut S, +) -> Result +where + S: SyncProgressSink, +{ + let clock = SystemSyncProgressClock; + run_current_sync_with_progress_and_clock(repo_root, progress, &clock) +} + +/// Production sync entry point with injectable progress sink and clock. +pub fn run_current_sync_with_progress_and_clock( + repo_root: &Path, + progress: &mut S, + clock: &C, +) -> Result +where + S: SyncProgressSink, + C: SyncProgressClock, +{ + progress.report(SyncProgressEvent::Started { + timestamp: timestamp(clock), + }); + let result = run_current_sync_without_progress(repo_root, progress); + progress.report(SyncProgressEvent::Finished { + timestamp: timestamp(clock), + }); + result +} + +fn run_current_sync_without_progress( + repo_root: &Path, + progress: &mut S, +) -> Result +where + S: SyncProgressSink, +{ let storage_config = config::resolve_agent_trace_storage_runtime_config(repo_root) .map_err(|error| TraceSyncError::Runtime(format!("{error:#}")))?; let context = AgentTraceStorageContext { @@ -106,23 +217,85 @@ pub fn run_current_sync(repo_root: &Path) -> Result Result { + let mut progress = NoopSyncProgressSink; + run_sync_against_with_progress(repository_id, source_instance_id, db, client, &mut progress) +} + +#[cfg(test)] +pub(crate) fn run_sync_against_with_progress( + repository_id: &str, + source_instance_id: &str, + db: &RepositoryAgentTraceDb, + client: &AuthenticatedControlPlaneClient, + progress: &mut S, +) -> Result +where + S: SyncProgressSink, +{ + let clock = SystemSyncProgressClock; + run_sync_against_with_progress_and_clock( + repository_id, + source_instance_id, + db, + client, + progress, + &clock, + ) +} + +#[cfg(test)] +pub(crate) fn run_sync_against_with_progress_and_clock( + repository_id: &str, + source_instance_id: &str, + db: &RepositoryAgentTraceDb, + client: &AuthenticatedControlPlaneClient, + progress: &mut S, + clock: &C, +) -> Result +where + S: SyncProgressSink, + C: SyncProgressClock, +{ + progress.report(SyncProgressEvent::Started { + timestamp: timestamp(clock), + }); + let result = + run_sync_against_without_progress(repository_id, source_instance_id, db, client, progress); + progress.report(SyncProgressEvent::Finished { + timestamp: timestamp(clock), + }); + result +} + +fn run_sync_against_without_progress( + repository_id: &str, + source_instance_id: &str, + db: &RepositoryAgentTraceDb, + client: &AuthenticatedControlPlaneClient, + progress: &mut S, +) -> Result +where + S: SyncProgressSink, +{ let runtime = shared_runtime()?; let reader = AgentTraceExportReader::new(db); @@ -144,6 +317,7 @@ pub(crate) fn run_sync_against( "messages", |cursor, limit| reader.read_messages_after(cursor, limit), |request| runtime.block_on(client.ingest_messages(request)), + progress, )?; let parts = sync_one_stream( runtime, @@ -155,6 +329,7 @@ pub(crate) fn run_sync_against( "parts", |cursor, limit| reader.read_parts_after(cursor, limit), |request| runtime.block_on(client.ingest_parts(request)), + progress, )?; let diff_traces = sync_one_stream( runtime, @@ -166,6 +341,7 @@ pub(crate) fn run_sync_against( "diff_traces", |cursor, limit| reader.read_diff_traces_after(cursor, limit), |request| runtime.block_on(client.ingest_diff_traces(request)), + progress, )?; let agent_traces = sync_one_stream( runtime, @@ -177,6 +353,7 @@ pub(crate) fn run_sync_against( "agent_traces", |cursor, limit| reader.read_agent_traces_after(cursor, limit), |request| runtime.block_on(client.ingest_agent_traces(request)), + progress, )?; Ok(AgentTraceSyncReport { @@ -207,6 +384,7 @@ fn sync_one_stream( stream_label: &'static str, mut read_after: ReadFn, mut ingest: IngestFn, + progress: &mut impl SyncProgressSink, ) -> Result where T: AgentTraceExportRow + Clone, @@ -216,6 +394,7 @@ where ) -> Result, { let terminal: RefCell> = RefCell::new(None); + let uploaded = RefCell::new(0usize); let outcome = sync_stream( initial_cursor, @@ -232,10 +411,25 @@ where rows: rows.to_vec(), }; match ingest(&request) { - Ok(response) => BatchAttemptOutcome::Accepted { - accepted: response.accepted, - cursor: response.cursor, - }, + Ok(response) => { + let last_row_id = rows + .last() + .expect("rows checked non-empty above") + .source_row_id(); + if response.accepted == rows.len() && response.cursor == last_row_id { + *uploaded.borrow_mut() += rows.len(); + progress.report(SyncProgressEvent::BatchAccepted { + stream: stream_label, + batch_rows: rows.len(), + uploaded: *uploaded.borrow(), + cursor: response.cursor, + }); + } + BatchAttemptOutcome::Accepted { + accepted: response.accepted, + cursor: response.cursor, + } + } Err(ControlPlaneError::Conflict(_)) => BatchAttemptOutcome::Conflict, Err(error) if is_stream_terminal(&error) => { *terminal.borrow_mut() = Some(error); @@ -264,12 +458,20 @@ where source, })?; - Ok(StreamSyncReport { + let report = StreamSyncReport { uploaded: outcome.uploaded, initial_cursor: outcome.initial_cursor, final_cursor: outcome.final_cursor, batches: outcome.batches, - }) + }; + progress.report(SyncProgressEvent::StreamCompleted { + stream: stream_label, + uploaded: report.uploaded, + cursor: report.final_cursor, + batches: report.batches, + }); + + Ok(report) } /// A control-plane failure that cannot be resolved by reconciling with @@ -320,6 +522,7 @@ mod tests { use std::path::PathBuf; use std::time::{SystemTime, UNIX_EPOCH}; + use chrono::{DateTime, Utc}; use serde_json::json; use super::*; @@ -426,6 +629,21 @@ mod tests { .expect("seed agent_trace"); } + fn seed_messages(db: &RepositoryAgentTraceDb, count: usize) { + db.insert_messages( + (1..=count) + .map(|index| InsertMessageInsert { + session_id: "sess-progress".to_string(), + message_id: format!("msg-progress-{index}"), + role: MessageRole::User, + generated_at_unix_ms: 1_700_000_000_000 + + i64::try_from(index).expect("test message count fits in i64"), + }) + .collect(), + ) + .expect("seed progress messages"); + } + fn state_response( messages: i64, parts: i64, @@ -446,6 +664,134 @@ mod tests { json!({ "accepted": 1, "cursor": cursor }) } + struct FixedProgressClock { + timestamps: RefCell>>, + } + + impl SyncProgressClock for FixedProgressClock { + fn now(&self) -> DateTime { + self.timestamps.borrow_mut().remove(0) + } + } + + fn fixed_progress_clock() -> FixedProgressClock { + FixedProgressClock { + timestamps: RefCell::new(vec![ + DateTime::parse_from_rfc3339("2026-01-02T03:04:05Z") + .expect("valid start timestamp") + .with_timezone(&Utc), + DateTime::parse_from_rfc3339("2026-01-02T03:04:06Z") + .expect("valid end timestamp") + .with_timezone(&Utc), + ]), + } + } + + #[test] + fn progress_events_cover_batches_empty_streams_and_fixed_order() { + let db_path = unique_test_db_path("progress-events"); + let db = RepositoryAgentTraceDb::new_at(&db_path).expect("test DB should open"); + let metadata = db + .verify_or_initialize_repository_metadata("repo-progress-events") + .expect("metadata should initialize"); + seed_messages(&db, 201); + + let server = TestHttpServer::start(); + server.queue_response(CannedResponse::json(200, &state_response(0, 0, 0, 0))); + server.queue_response(CannedResponse::json( + 200, + &json!({ + "accepted": 100, + "cursor": 100, + }), + )); + server.queue_response(CannedResponse::json( + 200, + &json!({ + "accepted": 100, + "cursor": 200, + }), + )); + server.queue_response(CannedResponse::json( + 200, + &json!({ + "accepted": 1, + "cursor": 201, + }), + )); + let client = test_client(&server); + let events = RefCell::new(Vec::new()); + let clock = fixed_progress_clock(); + + let report = run_sync_against_with_progress_and_clock( + &metadata.repository_id, + &metadata.source_instance_id, + &db, + &client, + &mut |event| events.borrow_mut().push(event), + &clock, + ) + .expect("sync should succeed"); + + assert_eq!(report.streams.messages.uploaded, 201); + assert_eq!(report.streams.messages.batches, 3); + assert_eq!( + events.into_inner(), + vec![ + SyncProgressEvent::Started { + timestamp: "2026-01-02T03:04:05Z".to_string(), + }, + SyncProgressEvent::BatchAccepted { + stream: "messages", + batch_rows: 100, + uploaded: 100, + cursor: 100, + }, + SyncProgressEvent::BatchAccepted { + stream: "messages", + batch_rows: 100, + uploaded: 200, + cursor: 200, + }, + SyncProgressEvent::BatchAccepted { + stream: "messages", + batch_rows: 1, + uploaded: 201, + cursor: 201, + }, + SyncProgressEvent::StreamCompleted { + stream: "messages", + uploaded: 201, + cursor: 201, + batches: 3, + }, + SyncProgressEvent::StreamCompleted { + stream: "parts", + uploaded: 0, + cursor: 0, + batches: 0, + }, + SyncProgressEvent::StreamCompleted { + stream: "diff_traces", + uploaded: 0, + cursor: 0, + batches: 0, + }, + SyncProgressEvent::StreamCompleted { + stream: "agent_traces", + uploaded: 0, + cursor: 0, + batches: 0, + }, + SyncProgressEvent::Finished { + timestamp: "2026-01-02T03:04:06Z".to_string(), + }, + ] + ); + + remove_test_db(&db_path); + } + #[test] fn full_sync_uploads_all_four_streams_and_second_run_is_naturally_incremental() { let db_path = unique_test_db_path("full-sync"); @@ -619,6 +965,50 @@ mod tests { remove_test_db(&db_path); } + #[test] + fn progress_events_end_after_terminal_failure() { + let db_path = unique_test_db_path("progress-failure"); + let db = RepositoryAgentTraceDb::new_at(&db_path).expect("test DB should open"); + let metadata = db + .verify_or_initialize_repository_metadata("repo-progress-failure") + .expect("metadata should initialize"); + seed_one_row_per_stream(&db); + + let server = TestHttpServer::start(); + server.queue_response(CannedResponse::json(200, &state_response(0, 0, 0, 0))); + server.queue_response(CannedResponse::json( + 404, + &json!({"message": "unknown ingestion route"}), + )); + let client = test_client(&server); + let events = RefCell::new(Vec::new()); + let clock = fixed_progress_clock(); + + let error = run_sync_against_with_progress_and_clock( + &metadata.repository_id, + &metadata.source_instance_id, + &db, + &client, + &mut |event| events.borrow_mut().push(event), + &clock, + ) + .expect_err("terminal batch failure should be reported"); + + assert!(matches!(error, TraceSyncError::Stream { .. })); + assert_eq!( + events.into_inner(), + vec![ + SyncProgressEvent::Started { + timestamp: "2026-01-02T03:04:05Z".to_string(), + }, + SyncProgressEvent::Finished { + timestamp: "2026-01-02T03:04:06Z".to_string(), + }, + ] + ); + remove_test_db(&db_path); + } + #[test] fn malformed_2xx_batch_response_still_reconciles_via_state() { let db_path = unique_test_db_path("malformed-batch"); diff --git a/context/architecture.md b/context/architecture.md index f6246885..d606e74b 100644 --- a/context/architecture.md +++ b/context/architecture.md @@ -105,7 +105,7 @@ The repository includes a new placeholder Rust binary crate at `cli/`. - `cli/src/app.rs` provides the clap-based argument dispatch loop with deterministic help/setup execution, bare-command help routing for `sce auth` and `sce config`, centralized stream routing (`stdout` success payloads, `stderr` redacted diagnostics), stable class-based exit-code mapping (`2` parse, `3` validation, `4` runtime, `5` dependency), and stable class-based stderr diagnostic codes (`SCE-ERR-PARSE`, `SCE-ERR-VALIDATION`, `SCE-ERR-RUNTIME`, `SCE-ERR-DEPENDENCY`) with default `Try:` remediation injection when missing. - The app runtime now moves through explicit startup phases in `cli/src/app.rs`: dependency bootstrapping (`perform_dependency_check`), startup context construction (`build_startup_context`), runtime initialization (`initialize_runtime`), command parse/execute inside telemetry subscriber context (`run_command_lifecycle`, `parse_command_phase` plus `services::app_support::execute_command_phase`), and final output rendering through `services::app_support::render_run_outcome`. `AppRuntime` owns the concrete production logger, no-op telemetry runtime, filesystem ops, git ops, static `CommandRegistry`, and startup-diagnostic state across those phases; `RunOutcome` carries final render data with an optional generic logger implementing `services::observability::traits::Logger`, so render support can log classified errors without production-logger type coupling. If a telemetry implementation attempts to invoke the command action more than once, dispatch returns a runtime-classified error instead of panicking or reusing consumed arguments. - `AppContext` is the CLI's borrowed dependency view in `cli/src/app.rs`: it is generic over logger, telemetry, filesystem, and git capability implementations and stores references plus an optional `repo_root: Option` instead of owning `Arc` trait objects. Because it borrows from `AppRuntime`, `AppContext` is a lightweight, short-lived view and must not be stored long-term (e.g., in structs or across await points). Startup creates a context view over `AppRuntime`'s concrete production dependencies with `repo_root` set to `None`; command paths can derive repo-root-scoped context views through the `ContextWithRepoRoot` accessor trait / `AppContext::with_repo_root(...)`, which reuses the same borrowed dependencies while attaching the resolved root. Narrow accessor traits expose associated concrete capability types for logger, telemetry, fs, and git (`&Self::...`) plus repo-root access, so call sites can express capability requirements without erasing the borrowed dependencies back to trait objects; lifecycle providers consume the repo-root accessor rather than the full context type. -- Command parse-time conversion and run-time handling are separated by an internal static `RuntimeCommand` seam. `cli/src/services/command_registry.rs` defines the `RuntimeCommand` enum with variants for help/help-text, version, completion, auth, config, setup, doctor, hooks, policy, and trace, plus a deterministic `CommandRegistry` name catalog populated by `build_default_registry()`. `parse_command_phase` in `cli/src/app.rs` delegates clap-output conversion to `cli/src/services/parse/command_runtime.rs`, which owns clap error classification, help rendering bridges, and parsed-request-to-enum conversion while returning concrete enum values. Service-owned `command.rs` modules define command payload structs and generic execution methods with narrow context requirements: context-free commands accept any context, hooks requires logger access, setup/doctor require repo-root scoping, and central dispatch requires the union of logger plus repo-root-scoping capabilities. `services::app_support::execute_command_phase` emits lifecycle logs around `RuntimeCommand::execute(...)`; the enum performs the only central dispatch match and delegates business behavior to the service-owned command structs. +- Command parse-time conversion and run-time handling are separated by an internal static `RuntimeCommand` seam. `cli/src/services/command_registry.rs` defines the `RuntimeCommand` enum with variants for help/help-text, version, completion, auth, config, setup, doctor, hooks, policy, and trace, plus a deterministic `CommandRegistry` name catalog populated by `build_default_registry()`. `parse_command_phase` in `cli/src/app.rs` delegates clap-output conversion to `cli/src/services/parse/command_runtime.rs`, which owns clap error classification, help rendering bridges, and parsed-request-to-enum conversion while returning concrete enum values. Service-owned `command.rs` modules define command payload structs and generic execution methods with narrow context requirements: context-free commands accept any context, hooks requires logger access, setup/doctor require repo-root scoping, and central dispatch requires the union of logger plus repo-root-scoping capabilities. `services::app_support::execute_command_phase` emits lifecycle logs around `RuntimeCommand::execute_with_stderr(...)`; the enum performs the only central dispatch match and delegates business behavior to the service-owned command structs, with trace sync receiving the app-owned stderr writer for format-gated progress. - Startup observability bootstrapping in `cli/src/app.rs` still tolerates invalid default-discovered config files by continuing with degraded defaults plus `sce.config.invalid_config` warn-level logs, but the warning/logging work is now isolated behind the startup-context and runtime-initialization phases rather than one inline startup function. - `cli/src/services/observability.rs` provides deterministic runtime observability controls and rendering for app lifecycle logs, including shared config-resolved threshold/format and `log_dir` inputs with precedence `env > config file > defaults` for non-flag observability keys, stable event identifiers, severity filtering, the forced-emission warning path used for invalid discovered config startup diagnostics, stderr primary emission, redaction-safe emission through the shared security helper, and log-directory writes with bounded retention. Config resolution also carries a positive config-file/default-only `log_file_retention_limit` (`10` by default) into startup observability config and `sce config show`; the concrete logger stores that resolved value and threads it through primary and v2 cleanup. When `log_dir` resolves from `SCE_LOG_DIR`, config, or the `/sce/logs` default, each enabled or forced log operation selects `/sce-.log` or `/sce--.log` using the machine-local date and optional logger session context, with deterministic percent-encoding for unsafe session filename bytes; after successfully writing a newly created selected file, retention keeps the configured number of newest direct regular `*.log` files by mtime plus path/name tie-break and fails open on cleanup errors. Its `observability::traits` submodule exposes the current `Logger` API with `Option<&str>` session context plus object-safe `Telemetry` trait boundaries and `NoopLogger`; the concrete observability logger and telemetry runtime still own behavior and implement those traits. `services::app_support::render_run_outcome` consumes the logger through that trait boundary when logging classified errors and stdout-write failures. - `cli/src/services/observability.rs` no longer owns duplicate log enums or parsing helpers; it consumes the canonical primitive seam from `cli/src/services/config/mod.rs` and stays focused on logger and telemetry runtime behavior. diff --git a/context/cli/agent-trace-sync-command.md b/context/cli/agent-trace-sync-command.md index 3ae5da93..236b3237 100644 --- a/context/cli/agent-trace-sync-command.md +++ b/context/cli/agent-trace-sync-command.md @@ -28,7 +28,7 @@ flowchart LR - **Credential runtime boundary:** `AuthenticatedControlPlaneClient` keeps the synchronous `CredentialStore` behind an `Arc` and runs every token-storage `load`/`save` through `tokio::task::spawn_blocking`. The underlying encrypted auth DB and Linux Secret Service/zbus APIs are blocking and may create their own Tokio runtime, so they must never execute directly inside the async control-plane request future. Token refresh and HTTP requests remain asynchronous; only credential persistence crosses the blocking boundary. - **control plane** is the sole source of cursor truth: every invocation starts from `POST /agent-trace/ingestion/state`, uploads via `POST /agent-trace/ingestion/batch`, and advances a stream's cursor only from a validated batch response (`accepted == rows.len()` and `cursor == rows.last().sourceRowId`), never by inferring `cursor + rows.len()`. -The four streams (`messages`, `parts`, `diff_traces`, `agent_traces`) are independent and synchronized in that fixed order within one invocation. +The four streams (`messages`, `parts`, `diff_traces`, `agent_traces`) are independent and synchronized in that fixed order within one invocation. Text mode reports a UTC RFC3339 start timestamp before the first control-plane request, each validated accepted batch's size, cumulative uploaded rows, and current cursor, stream completion, and a terminal UTC RFC3339 end timestamp after success or failure through deterministic newline-delimited flushed lines on `stderr`; an empty stream reports that no new rows were uploaded. The timestamps come from an injectable clock for deterministic tests and do not alter the sync protocol or error classification. JSON mode uses a no-op progress sink and retains its JSON-only output contract without progress or lifecycle timestamps. ## No-local-persistence invariants @@ -58,3 +58,4 @@ Because every invocation starts from the control plane's authoritative `/state` - [agent-trace-storage.md](agent-trace-storage.md) — the repository-scoped storage resolver sync reuses from `sce trace status`. - [agent-trace-export-readers.md](../sce/agent-trace-export-readers.md) — the read-only local export boundary sync reads through. - [auth-db.md](../sce/auth-db.md) — encrypted WorkOS credential storage sync authenticates through. +- [Trace-sync progress stream contract](../decisions/2026-08-13-trace-sync-progress-stream-contract.md) — stderr progress/timestamps and stdout/JSON compatibility boundary. diff --git a/context/cli/trace-command.md b/context/cli/trace-command.md index 6a4ec3da..c81b19b5 100644 --- a/context/cli/trace-command.md +++ b/context/cli/trace-command.md @@ -82,7 +82,7 @@ Text rendering shows discovery summary, totals, and a `By database` table with ` `run_current_sync(repo_root)` resolves the current repository's Agent Trace storage through the same `agent_trace_storage` path `sce trace status` uses (not the hook-runtime resolver), builds an `AuthenticatedControlPlaneClient` from the resolved `control_plane_base_url`/`workos_client_id` config, and uses `https://sce.crocoderlab.dev` as the baked control-plane base when no override is configured. This control-plane host is separate from the SCE web/schema URL owned by `SCE_WEB_BASE_URL`. Sync calls the control-plane `/agent-trace/ingestion/state` endpoint once, then synchronizes the four independent capture streams (`messages`, `parts`, `diff_traces`, `agent_traces`, in that fixed order) via the local `AgentTraceExportReader` and the shared per-stream reconciliation engine, producing an `AgentTraceSyncReport`. A genuinely ambiguous batch outcome (`5xx`, transport failure, invalid response) reconciles by refetching `/state`; a terminal control-plane failure (missing/invalid credentials, `400`, `403`) fails the stream immediately without an extra network call, so a `403` never mutates local repository metadata or retries. No local sync cursor, cursor file, or database is created — every invocation starts from the authoritative `/state` cursors, so repeated runs are naturally incremental. -`render_sync::render(report, format)` renders the converged `AgentTraceSyncReport`. Text output is a `style::heading("Agent Trace sync complete.")` line, `Repository ID:`/`Source instance ID:` lines, then a padded table with one row per stream (`Stream`, `Uploaded`, `Final cursor`) in the fixed `messages → parts → diff_traces → agent_traces` order — no per-batch or per-row detail is printed. JSON output carries `status`, `command`, `subcommand`, `repositoryId`, `sourceInstanceId`, and `streams.{messages,parts,diffTraces,agentTraces}`, each with `uploaded`/`initialCursor`/`finalCursor`/`batches`; the JSON stream keys are camelCase (`diffTraces`/`agentTraces`) even though the internal `StreamSyncReports` struct fields are `diff_traces`/`agent_traces`. `TraceCommand::execute` dispatches `TraceSubcommandRequest::Sync { format }` to `render_sync::render`, completing the command surface end to end. +`render_sync::render(report, format)` renders the converged `AgentTraceSyncReport`. In text mode, sync first emits deterministic live progress lines to `stderr`: a start line, one line for each accepted batch with the stream, batch size, cumulative uploaded rows, and server cursor, then one completion line per stream; an empty stream reports that no new rows were uploaded. These lines are newline-delimited and flushed as events arrive, so a slow upload is observable before the final report. The start line includes an injected-clock UTC RFC3339 timestamp and is emitted before the initial `/state` request; a terminal end line is emitted after successful completion or failure, preserving the classified error returned to the app. The final text output remains a `style::heading("Agent Trace sync complete.")` line, `Repository ID:`/`Source instance ID:` lines, then a padded table with one row per stream (`Stream`, `Uploaded`, `Final cursor`) in the fixed `messages → parts → diff_traces → agent_traces` order — no per-batch or per-row detail is added to the `stdout` payload. JSON mode uses a no-op progress sink and emits no human progress or lifecycle timestamps; its `stdout` output carries `status`, `command`, `subcommand`, `repositoryId`, `sourceInstanceId`, and `streams.{messages,parts,diffTraces,agentTraces}`, each with `uploaded`/`initialCursor`/`finalCursor`/`batches`; the JSON stream keys are camelCase (`diffTraces`/`agentTraces`) even though the internal `StreamSyncReports` struct fields are `diff_traces`/`agent_traces`. `TraceCommand::execute` dispatches `TraceSubcommandRequest::Sync { format }` through the format-specific progress sink and then to `render_sync::render`, completing the command surface end to end. ## Related context @@ -91,4 +91,5 @@ Text rendering shows discovery summary, totals, and a `By database` table with ` - [checkout-identity.md](checkout-identity.md) — checkout identity diagnostics and never-touch on-disk handling of pre-migration DB files. - [default-path-catalog.md](default-path-catalog.md) — Agent Trace DB path ownership. - [styling-service.md](styling-service.md) — heading helper used by text renderers. +- [Trace-sync progress stream contract](../decisions/2026-08-13-trace-sync-progress-stream-contract.md) — stderr progress/timestamps and stdout/JSON compatibility boundary. - [../sce/agent-trace-db.md](../sce/agent-trace-db.md) — Agent Trace DB schema and migration ownership. diff --git a/context/context-map.md b/context/context-map.md index 29b10df1..f36d2c49 100644 --- a/context/context-map.md +++ b/context/context-map.md @@ -17,7 +17,7 @@ Feature/domain context: - `context/cli/patch-service.md` (standalone patch domain model, parser, JSON load helpers, and set operations in `cli/src/services/patch.rs` for in-memory parsed unified-diff representation, capturing only touched lines plus minimal per-file/per-hunk metadata, supporting both `Index:` SVN-style and `diff --git` git-style formats, with `ParseError` for actionable malformed-input diagnostics, `PatchLoadError`/`load_patch_from_json`/`load_patch_from_json_bytes` for storage-agnostic JSON reconstruction, `intersect_patches` for target-shaped overlap with exact-match-first and historical `kind`+`content` fallback semantics plus matched-constructed-line `session_id` and matched-constructed-hunk `model_id` provenance inheritance, and `combine_patches` for ordered patch combination with later-wins conflict resolution plus winning-hunk `model_id` provenance inheritance; `parse_patch`, `intersect_patches`, and `combine_patches` are consumed by the active post-commit hook runtime) - `context/cli/structured-patch-service.md` (Claude structured editor-hook derivation in `cli/src/services/structured_patch.rs`, including `Write` structured-update hunks, `Write` `tool_input.content` create fallback, `Edit` structured patches, deterministic skip reasons, `ParsedPatch` output semantics, and Rust golden fixture coverage) - `context/cli/styling-service.md` (CLI text-mode output styling with `owo-colors` and `comfy-table`, TTY/`NO_COLOR` policy, shared helper API for human-facing surfaces, and per-column right-to-left RGB gradient banner rendering) -- `context/cli/trace-command.md` (`sce trace` command group: repository-scoped-only discovery of `/sce/repos//agent-trace.db` with mtime-desc + repository-id tiebreak alias assignment and required-table readiness probing, no `--legacy` flag or checkout-scoped access, implemented `sce trace db shell` current-repository opening plus alias/repository-ID resolution without external `turso`, implemented `sce trace db list` text + JSON rendering using `services::style::heading` with scope/identifier fields, implemented repository-scoped `sce trace status` with checkout ID diagnostics, implemented `sce trace status --all` aggregation across discovered repository DBs, implemented `sce trace sync` control-plane synchronization orchestration with documented text/JSON rendering complete, and the completed removal of `sce doctor dbs` whose discovery scan/rendering moved into `services::trace`) +- `context/cli/trace-command.md` (`sce trace` command group: repository-scoped-only discovery of `/sce/repos//agent-trace.db` with mtime-desc + repository-id tiebreak alias assignment and required-table readiness probing, no `--legacy` flag or checkout-scoped access, implemented `sce trace db shell` current-repository opening plus alias/repository-ID resolution without external `turso`, implemented `sce trace db list` text + JSON rendering using `services::style::heading` with scope/identifier fields, implemented repository-scoped `sce trace status` with checkout ID diagnostics, implemented `sce trace status --all` aggregation across discovered repository DBs, implemented `sce trace sync` control-plane synchronization orchestration with deterministic text-mode `stderr` progress and unchanged JSON/text rendering contracts, and the completed removal of `sce doctor dbs` whose discovery scan/rendering moved into `services::trace`) - `context/cli/agent-trace-sync-command.md` (composed local-to-control-plane `sce trace sync` architecture: the `hooks/plugins → repository Agent Trace DB → AgentTraceExportReader → sce trace sync → HTTPS + WorkOS Bearer → control plane` data flow, the `sce auth login` / `cd ` / `sce trace sync` user flow, the no-local-cursor/no-`agent-trace-sync.db`/no-Turso-Sync/no-`BridgeLock`/no-local-DWH invariants, and `401`/`409`/ambiguous-batch-failure recovery semantics) - `context/cli/config-precedence-contract.md` (implemented `sce config` show/validate command contract, deterministic `flags > env > config file > defaults` resolution order, focused `config/resolver.rs` ownership for config discovery/merge/runtime precedence plus default-discovered invalid-file degradation, focused `config/render.rs` ownership for `show`/`validate` text+JSON output construction, canonical `$schema` acceptance for startup-loaded `sce/config.json` files, shared auth-key env/config/optional baked-default support starting with `workos_client_id`, shared runtime resolution for flat logging observability keys including `log_dir` / `SCE_LOG_DIR` with `/sce/logs` defaulting plus config-file/default-only positive `log_file_retention_limit`, config-file-only `agent_trace.repository_id`/`agent_trace.repository_remote` repository-identity keys with default remote `origin`, the catalog-derived `integrations.optional_workflows` optional-workflow selection key, JSON-pointer-prefixed schema-validation errors, canonical Pkl-generated `sce/config.json` schema ownership plus CLI embedding/reuse contract including `policies.attribution_hooks.enabled` default-true/explicit-false opt-out metadata, config-file selection order, `show` provenance output, and trimmed `validate` output contract) - `context/cli/capability-traits.md` (current broad CLI capability seam in `cli/src/services/capabilities.rs`, including `FsOps`/`StdFsOps`, `GitOps`/`ProcessGitOps`, git root/hooks resolution behavior, compile-time-typed borrowed AppContext wiring with associated-type narrow capability accessors plus `ContextWithRepoRoot` repo-root-scoped context derivation, generic command execution bounds, and test-only unimplemented stubs; current service internals do not consume fs/git traits until later lifecycle migration tasks) @@ -113,4 +113,5 @@ Recent decision records: - `context/decisions/2026-07-17-retire-legacy-agent-trace-db.md` (retire the checkout-scoped Agent Trace DB surface; `RepositoryAgentTraceDb` is the sole adapter, no `sce trace --legacy`, no global/checkout fallback path; pre-migration on-disk files are never touched and no longer inspectable via the CLI) - `context/decisions/2026-08-10-agent-trace-source-instance-id.md` (adds `source_instance_id` as a physical-database-lineage identity on `repository_metadata`, independent of and never derived from `repository_id`; concurrency-safe atomic claim; local storage identity only, no remote-ingestion architecture designed) - `context/decisions/2026-08-11-separate-control-plane-and-sce-web-urls.md` (separates the dedicated control-plane sync default from the SCE web and config-schema URL owner while preserving the existing override seam and ingestion contract) +- `context/decisions/2026-08-13-trace-sync-progress-stream-contract.md` (keeps trace-sync progress and lifecycle timestamps on stderr while preserving stdout payload and JSON silence) - `context/decisions/2026-08-07-git-hook-managed-block-cooperation.md` (SCE-installed git hooks are a bounded in-place editor, not an exclusive owner: hook ownership is decided structurally by the SCE managed-block marker pair or a legacy guidance-URL marker, a foreign hook's bytes are preserved as an exact prefix with the block appended after them, and coexistence with third-party hook managers is cooperative, not authoritative) diff --git a/context/decisions/2026-08-13-trace-sync-progress-stream-contract.md b/context/decisions/2026-08-13-trace-sync-progress-stream-contract.md new file mode 100644 index 00000000..659aebe5 --- /dev/null +++ b/context/decisions/2026-08-13-trace-sync-progress-stream-contract.md @@ -0,0 +1,53 @@ +# Decision: Keep trace-sync progress on stderr while stdout remains payload-only + +Date: 2026-08-13 +Status: Accepted +Plan: `context/plans/trace-sync-progress.md` +Task: T01, T02, T03, T04 + +## Context + +`sce trace sync` needs observable feedback during slow text-mode uploads, but CLI callers depend on stdout containing the command payload and JSON mode remaining machine-readable. The completed plan adds accepted-batch progress plus UTC lifecycle timestamps and must establish a durable stream boundary for this user-visible behavior. + +## Decision + +Emit human-readable `sce trace sync` progress and lifecycle timestamps only on `stderr`; keep the final text report and the unchanged JSON payload on `stdout`, with JSON mode emitting no progress or lifecycle text. + +## Rationale + +This provides live feedback without contaminating redirected or piped command payloads and preserves the existing machine-readable JSON contract. A single format-gated reporter also keeps the behavior deterministic and limits progress to presentation rather than sync protocol or persistence state. + +## Alternatives considered + +- **Emit progress on stdout** — would mix transient lines with the final payload and break consumers that redirect or parse command output. +- **Add progress fields or messages to JSON** — would change the established machine-readable schema and make JSON unsuitable for callers expecting only the payload. +- **Use terminal-only redraw output** — would make redirected human output ambiguous and add unnecessary TTY-specific behavior. + +## Compatibility and risks + +- Text-mode callers that separately capture stderr will now receive progress and lifecycle lines; stdout payload shape remains unchanged. +- JSON consumers retain the existing stdout schema and receive no human side channel. Progress output remains newline-delimited, flushed, credential-free, and limited to batch/stream summaries. + +## Guardrails + +- Do not add progress fields to the JSON report or alter final text/JSON renderers. +- Keep progress on stderr, preserve fixed stream order, and emit no per-row payloads, credentials, raw responses, or local database rows. +- Keep timestamps UTC RFC3339 and report start before the first control-plane request and finish after terminal success or failure. + +## Consequences + +- Operators can observe slow text-mode synchronization before the final report completes. +- CLI integrations can continue treating stdout as the command payload and JSON mode as silent apart from its JSON stdout result. +- The stderr contract now includes trace-sync progress as an intentional presentation channel. + +## Follow-up + +None. + +## References + +- Plan: [`trace-sync-progress`](../plans/trace-sync-progress.md) +- Task: `T01, T02, T03, T04` +- Current-state context: [`sce trace command`](../cli/trace-command.md), [`Agent Trace sync architecture`](../cli/agent-trace-sync-command.md), [`CLI stdout/stderr contract`](../sce/cli-stdout-stderr-contract.md) +- Evidence: [`trace sync orchestration`](../../cli/src/services/trace/sync.rs), [`trace command`](../../cli/src/services/trace/command.rs), [`Validation Report`](../plans/trace-sync-progress.md) +- Related decision: [`Migrate from lexopt to clap for CLI Argument Parsing`](2026-03-09-migrate-lexopt-to-clap.md) diff --git a/context/glossary.md b/context/glossary.md index 7844ab29..38397a73 100644 --- a/context/glossary.md +++ b/context/glossary.md @@ -114,7 +114,7 @@ - `sce stderr error-code taxonomy`: Stable user-facing diagnostic code classes emitted by `cli/src/app.rs` (`SCE-ERR-PARSE`, `SCE-ERR-VALIDATION`, `SCE-ERR-RUNTIME`, `SCE-ERR-DEPENDENCY`) via `Error []: ...` stderr formatting. - `class-default Try guidance injection`: `cli/src/app.rs` diagnostic behavior that appends `Try:` remediation text by failure class only when an error message does not already include `Try:` guidance. - `sce observability baseline`: App-runtime logging contract in `cli/src/services/observability.rs` and `cli/src/app.rs` with config-resolved observability inputs, deterministic env-over-config-file-over-default precedence for non-flag logging keys, default-backed `log_dir` / `SCE_LOG_DIR` file routing by machine-local date plus optional session filename partitioning, creation-triggered retention of direct regular `*.log` files to 10 entries, stable lifecycle `event_id` values, and stderr primary emission. -- `sce stdout/stderr contract`: App-level stream routing contract in `cli/src/app.rs` where command success payloads are emitted on stdout only, while redacted user-facing diagnostics are emitted on stderr. +- `sce stdout/stderr contract`: App-level stream routing contract in `cli/src/app.rs` where command success payloads are emitted on stdout only, while redacted user-facing diagnostics and text-mode `sce trace sync` progress are emitted on stderr; JSON sync emits no human progress. - `SCE_LOG_LEVEL`: Optional runtime env key for `sce` observability threshold; allowed values are `error`, `warn`, `info`, and `debug`, defaulting to `error` when unset. - `SCE_LOG_FORMAT`: Optional runtime env key for `sce` observability record format; allowed values are `text` and `json`, defaulting to `text` when unset. - `SCE_LOG_FILE`: Optional runtime env key for `sce` observability file sink path; when set, rendered observability lines are mirrored to this file path with parent-directory auto-create behavior. diff --git a/context/overview.md b/context/overview.md index 89832012..348196c5 100644 --- a/context/overview.md +++ b/context/overview.md @@ -8,7 +8,7 @@ It also includes a Rust CLI (`sce`) for Shared Context Engineering workflows: au - **Exit codes:** `2` parse, `3` validation, `4` runtime, `5` dependency failure (see `context/sce/cli-exit-code-contract.md`). - **Stderr diagnostics:** stable `SCE-ERR-{PARSE,VALIDATION,RUNTIME,DEPENDENCY}` codes with class-default `Try:` remediation (see `context/sce/cli-error-code-taxonomy.md`). -- **Stdout/stderr:** command payloads on stdout only; redacted diagnostics on stderr (see `context/sce/cli-stdout-stderr-contract.md`). +- **Stdout/stderr:** command payloads on stdout only; redacted diagnostics and text-mode `sce trace sync` progress on stderr, while JSON sync remains silent (see `context/sce/cli-stdout-stderr-contract.md`). - **Observability:** config-resolved logging to stderr, optional dated/session-partitioned `log_dir` / `SCE_LOG_DIR` files with retention (see `context/sce/cli-observability-contract.md`). - **Config precedence:** `flags > env > config file > defaults` (see `context/cli/config-precedence-contract.md`). - **Attribution hooks:** enabled by default, gated by staged-diff AI-overlap preflight; `SCE_ATTRIBUTION_HOOKS_DISABLED` opt-out (see `context/sce/agent-trace-commit-msg-coauthor-policy.md`). @@ -19,7 +19,7 @@ Its command loop is implemented with `clap` derive-based argument parsing and `a The command loop now enforces a stable exit-code contract in `cli/src/app.rs`: `2` parse failures, `3` invocation validation failures, `4` runtime failures, and `5` dependency startup failures. The same runtime also emits stable user-facing stderr error classes (`SCE-ERR-PARSE`, `SCE-ERR-VALIDATION`, `SCE-ERR-RUNTIME`, `SCE-ERR-DEPENDENCY`) using deterministic `Error []: ...` diagnostics with class-default `Try:` remediation appended when missing. The app runtime now also includes a structured observability baseline in `cli/src/services/observability.rs`: deterministic env-controlled log threshold/format (`SCE_LOG_LEVEL` defaults to `error`; `SCE_LOG_FORMAT` defaults to `text`), default-backed log-directory routing (`SCE_LOG_DIR` / config-file `log_dir` / `/sce/logs`) with per-operation machine-local dated file selection, optional session filename partitioning, and creation-triggered retention of direct regular `*.log` files to 10 entries, stable lifecycle event IDs, stderr primary emission so stdout command payloads remain pipe-safe, and `observability::traits` boundaries for logger and telemetry behavior. -The app command dispatcher now enforces a centralized stdout/stderr stream contract in `cli/src/app.rs`: command success payloads are emitted on stdout only, while redacted user-facing diagnostics are emitted on stderr. `cli/src/app.rs` also now runs through explicit startup phases — dependency check, observability config resolution, runtime initialization, command parse/execute, and output rendering — with the app runtime carrying logger/telemetry plus static command-catalog state across those phases while preserving the existing exit-code and degraded-startup contracts. Within that lifecycle, `parse_command_phase` delegates clap-to-runtime conversion to `cli/src/services/parse/command_runtime.rs`, which returns a static `RuntimeCommand` enum, `services::app_support::execute_command_phase` logs around enum-owned `execute(...)` dispatch, and generic `RunOutcome` rendering logs classified errors through the logger trait boundary without coupling render support to the production logger type. Command payload structs for `help`, `version`, `completion`, `auth`, `config`, `setup`, `doctor`, and `hooks` live in service-owned `command.rs` files; `cli/src/services/command_registry.rs` owns the deterministic static command-name catalog and enum variants instead of boxed command trait objects. +The app command dispatcher now enforces a centralized stdout/stderr stream contract in `cli/src/app.rs`: command success payloads are emitted on stdout only, while redacted user-facing diagnostics and text-mode trace-sync progress are emitted on stderr; JSON trace sync remains silent. `cli/src/app.rs` also now runs through explicit startup phases — dependency check, observability config resolution, runtime initialization, command parse/execute, and output rendering — with the app runtime carrying logger/telemetry plus static command-catalog state across those phases while preserving the existing exit-code and degraded-startup contracts. Within that lifecycle, `parse_command_phase` delegates clap-to-runtime conversion to `cli/src/services/parse/command_runtime.rs`, which returns a static `RuntimeCommand` enum, `services::app_support::execute_command_phase` logs around enum-owned `execute_with_stderr(...)` dispatch, and generic `RunOutcome` rendering logs classified errors through the logger trait boundary without coupling render support to the production logger type. Command payload structs for `help`, `version`, `completion`, `auth`, `config`, `setup`, `doctor`, and `hooks` live in service-owned `command.rs` files; `cli/src/services/command_registry.rs` owns the deterministic static command-name catalog and enum variants instead of boxed command trait objects. The CLI now also enforces a shared output-format parser contract in `cli/src/services/output_format.rs`, with canonical `--format ` parsing and command-specific actionable invalid-value guidance reused by `config` and `version` services. A compile-safe service lifecycle seam also exists in `cli/src/services/lifecycle.rs`: `ServiceLifecycle` exposes default no-op `diagnose`, `fix`, and `setup` methods against the narrow `HasRepoRoot` accessor, uses lifecycle-owned health/fix/setup result types, and owns the shared static `LifecycleProvider` enum catalog/factory with deterministic config → local_db → auth_db → agent_trace_db → hooks ordering and no boxed provider aggregation. Hooks has a `services/hooks/lifecycle.rs` provider for hook rollout diagnosis/fix/setup, config has a `services/config/lifecycle.rs` provider for global/repo-local config validation plus repo-local config bootstrap, local_db has a `services/local_db/lifecycle.rs` provider for canonical local DB path health, parent-directory readiness/bootstrap, and `LocalDb::new()` setup, auth_db has a `services/auth_db/lifecycle.rs` provider for canonical auth DB path health, parent-directory readiness/bootstrap, and `AuthDb::new()` setup, and agent_trace_db has a `services/agent_trace_db/lifecycle.rs` provider for repository-scoped Agent Trace DB setup and repository DB path health/parent readiness from resolved repository identity, returning an actionable "requires a Git repository" diagnostic outside repository context (no global/checkout fallback path). Doctor runtime aggregates the full shared provider catalog for `diagnose` and `fix` and adapts lifecycle records into doctor-owned output records; setup command aggregates the shared provider catalog for `setup` with hooks included only when requested and adapts lifecycle setup outcomes before rendering setup-owned messages. Agent Trace lifecycle setup now resolves repository storage, creates/reuses checkout identity for diagnostics, and initializes `/sce/repos//agent-trace.db` via `RepositoryAgentTraceDb`; hook runtime lazy initialization uses the same repository storage resolver when setup has not prepared the DB or schema metadata is incomplete. The CLI now also includes a shared text styling service in `cli/src/services/style.rs` that provides deterministic color enablement via `owo-colors`, automatic TTY detection, and `NO_COLOR` compliance for human-facing text output; stdout help/text surfaces, stderr diagnostics, and interactive prompt-adjacent text now reuse that shared styling policy while JSON, completion, and other non-interactive/machine-readable flows remain unstyled. The service exports color-detection, conditional styling, help/diagnostic/label/prompt styling, and `banner_with_gradient()` helpers for use across command surfaces while preserving pipe-safe output for non-interactive environments. diff --git a/context/plans/agent-trace-sync-state-timeout.md b/context/plans/agent-trace-sync-state-timeout.md new file mode 100644 index 00000000..4030f37b --- /dev/null +++ b/context/plans/agent-trace-sync-state-timeout.md @@ -0,0 +1,93 @@ +# Plan: agent-trace-sync-state-timeout + +## Change summary + +`sce trace sync`'s `POST /agent-trace/ingestion/state` call currently runs +through `resilience::run_with_retry` with `STATE_RETRY_MAX_ATTEMPTS = 3` and a +10-second per-attempt timeout (`STATE_RETRY_TIMEOUT_MS`), defined in +`cli/src/services/agent_trace_sync/control_plane.rs`. This is the exact call +failing in the field: `Operation 'agent_trace_sync.ingestion_state' failed +after 3 attempt(s) (timeout=10000ms, backoff=250..2000ms)`. + +This plan removes the retry loop for that call (a single attempt instead of +up to three) and raises its per-attempt timeout from 10s to 60s. Both values +are already externalized as named constants consumed by one `RetryPolicy` +literal, so this is a narrow constant change plus the test coverage needed to +prove the new single-attempt-at-60s behavior, not a new mechanism. + +`POST /agent-trace/ingestion/batch` (`post_batch`) is untouched: it already +has no client-side timeout or retry wrapper today (batch reconciliation is +handled by the sync engine's own bounded `409`/ambiguous-failure logic, not +by this HTTP-layer policy), and this request is out of scope for the change. + +## Acceptance criteria + +- [x] AC1: A transient `5xx` response from `POST /agent-trace/ingestion/state` fails the call immediately after exactly one HTTP attempt instead of retrying up to three times. + - Validate: `cargo test --manifest-path cli/Cargo.toml --lib agent_trace_sync::control_plane -- ingestion_state` +- [x] AC2: `ingestion_state`'s per-attempt timeout is 60 seconds (`STATE_RETRY_TIMEOUT_MS == 60_000`), and the existing 401-refresh-and-retry-once authentication path (a separate mechanism from this policy) is unaffected. + - Validate: inspect `STATE_RETRY_MAX_ATTEMPTS`/`STATE_RETRY_TIMEOUT_MS` in `cli/src/services/agent_trace_sync/control_plane.rs`; `unexpected_401_refreshes_once_and_retries_once_on_success` and `unexpected_401_twice_fails_without_a_third_attempt` still pass unmodified. + +### Full validation + +- `nix flake check` (runs `cli-tests`, `cli-clippy`, `cli-fmt` among the repo's other checks) + +### Context sync + +- None. `context/cli/agent-trace-sync-command.md`'s recovery-semantics section describes `401`/`409`/ambiguous-batch-failure behavior qualitatively and names no specific attempt count or timeout value for `/state`, so it needs no edit for this change. + +## Constraints and non-goals + +- **In scope:** `STATE_RETRY_MAX_ATTEMPTS` and `STATE_RETRY_TIMEOUT_MS` in `cli/src/services/agent_trace_sync/control_plane.rs`, and the `control_plane.rs` unit tests needed to prove the new behavior. +- **Out of scope:** `post_batch`/`POST /agent-trace/ingestion/batch` (no existing client-side timeout to change); the `409`/ambiguous-failure reconciliation engine; the control-plane server (separate repository). +- **Constraints:** Reuse the existing `resilience::RetryPolicy`/`run_with_retry` mechanism as-is (`max_attempts: 1` still enforces the per-attempt timeout via `tokio::time::timeout`, per `resilience.rs`); do not introduce a new timeout/retry primitive for one call site. +- **Non-goal:** Making the retry/timeout values configurable (e.g. via `sce/config.json`'s `database_retry`-style namespace). Nothing in the request asked for that, and the existing `policies.database_retry` config namespace is scoped to local Turso databases, not control-plane HTTP calls. + +## Assumptions + +- "Remove retry attempt" means the transient-failure retry loop gated by `STATE_RETRY_MAX_ATTEMPTS` (currently 3, backed by exponential backoff) — not the unrelated, already-single-retry `401`-refresh-and-retry-once mechanism in `execute_authenticated`, which the user's error output never mentions and which this change leaves untouched. +- "Timeout... increased to 60 sec" means `STATE_RETRY_TIMEOUT_MS`, the only existing timeout knob on this call path (10,000 → 60,000). +- With `max_attempts = 1`, `STATE_RETRY_INITIAL_BACKOFF_MS`/`STATE_RETRY_MAX_BACKOFF_MS` become dead values (the backoff branch in `run_with_retry` never executes for a single-attempt policy). Left in place rather than removed: `RetryPolicy` requires all four fields, and `run_with_retry`'s failure message still reports the configured backoff window, matching the existing shape other `RetryPolicy` call sites use. + +## Task stack + +- [x] T01: `Make ingestion_state a single 60s attempt` (status:complete) + - Task ID: T01 + - Goal: Change `STATE_RETRY_MAX_ATTEMPTS` to `1` and `STATE_RETRY_TIMEOUT_MS` to `60_000` in `cli/src/services/agent_trace_sync/control_plane.rs`, and add test coverage proving a transient `5xx` on `/agent-trace/ingestion/state` is no longer retried. + - Boundaries (in/out of scope): In — the two constants, and one new (or adapted) unit test in `control_plane.rs`'s existing test module asserting single-attempt behavior on a transient failure (e.g. queue one `503` response and assert `server.call_count() == 1` and the call fails, mirroring the existing `TestHttpServer`/`CannedResponse` test scaffolding already used by the `401` tests in the same file). Out — `post_batch`, the sync engine's `409`/reconciliation logic, and any server-side change. + - Dependencies: none + - Done when: `STATE_RETRY_MAX_ATTEMPTS == 1` and `STATE_RETRY_TIMEOUT_MS == 60_000`; the new/adapted test demonstrates a transient failure fails after exactly one HTTP call; `unexpected_401_refreshes_once_and_retries_once_on_success` and `unexpected_401_twice_fails_without_a_third_attempt` still pass unchanged, showing the `401` path is independent of this policy. + - Implementation evidence: Set the state retry policy to one 60-second attempt, updated its API documentation, and added `transient_state_failure_fails_after_one_http_attempt`, which queues a `503`, asserts failure, and verifies exactly one HTTP call. + - Verification notes (commands or checks): `nix develop -c ./scripts/run-cli-cargo.sh test --manifest-path cli/Cargo.toml agent_trace_sync::control_plane` passed (27 tests, including both unchanged 401 tests); `nix develop -c ./scripts/run-cli-cargo.sh clippy --manifest-path cli/Cargo.toml -- -D warnings` passed; `nix develop -c cargo fmt --manifest-path cli/Cargo.toml -- --check` passed. + +## Open questions + +This is a client-side mitigation, not a fix for the diagnosed root cause. Earlier in this session, the actual `ingestion_state` timeouts were traced to the control-plane server (`packages/agent-trace/src/batch-store.ts` in the `control-plane` repository): `POST /agent-trace/ingestion/batch` holds a SQLite write-lock transaction for 75-115+ seconds because it awaits one network round-trip per row inside the transaction instead of batching them, and `/state`'s own write (`findOrCreateSource`) blocks behind that lock. A 60-second single-attempt timeout still fails whenever a concurrent batch upload runs longer than 60s — which was observed up to 115s — and removing the retry removes the one behavior (backoff + reattempt) that occasionally let a request through once the lock released. If the batch-store fix (batching the per-row inserts server-side) is in scope soon, consider whether this client-side change is still worth doing now versus after that fix lands, since post-fix the 10s timeout would likely stop firing on its own. Proceeding as requested either way. + +## Validation Report + +**Status:** validated +**Date:** 2026-08-13 + +### Commands run + +- `nix develop -c ./scripts/run-cli-cargo.sh test --manifest-path cli/Cargo.toml agent_trace_sync::control_plane` -> exit 0 (27 control-plane tests passed, including both unchanged 401 tests and the transient state-failure test) +- `nix develop -c ./scripts/run-cli-cargo.sh test --manifest-path cli/Cargo.toml --lib agent_trace_sync::control_plane -- ingestion_state` -> exit 101 (the package has no library target) +- `nix develop -c ./scripts/run-cli-cargo.sh test --manifest-path cli/Cargo.toml agent_trace_sync::control_plane -- ingestion_state` -> exit 0 (27 control-plane tests passed) +- `nix flake check` -> exit 0 (all flake checks passed) + +### Scaffolding removed + +- None. + +### Success-criteria verification + +- [x] AC1: A transient `5xx` response from `POST /agent-trace/ingestion/state` fails the call immediately after exactly one HTTP attempt instead of retrying up to three times. -> `transient_state_failure_fails_after_one_http_attempt` passed and verified exactly one HTTP call. +- [x] AC2: `ingestion_state`'s per-attempt timeout is 60 seconds (`STATE_RETRY_TIMEOUT_MS == 60_000`), and the existing 401-refresh-and-retry-once authentication path (a separate mechanism from this policy) is unaffected. -> Inspection confirmed `STATE_RETRY_TIMEOUT_MS == 60_000` and `STATE_RETRY_MAX_ATTEMPTS == 1`; both named 401 tests passed unmodified. + +### Failed checks and follow-ups + +- None. + +### Residual risks + +- The 60-second client timeout remains vulnerable to control-plane batch transactions observed to exceed 60 seconds, as described in Open questions. diff --git a/context/plans/trace-sync-progress.md b/context/plans/trace-sync-progress.md new file mode 100644 index 00000000..43c99b20 --- /dev/null +++ b/context/plans/trace-sync-progress.md @@ -0,0 +1,126 @@ +# Plan: trace-sync-progress + +## Change summary + +Improve `sce trace sync` human-facing feedback by emitting deterministic progress to `stderr` while a text-mode sync is running. The current command waits until all four streams finish before returning its concise report, leaving users with no indication that a slow or large sync is still active. JSON mode remains machine-readable and unchanged: it emits no progress messages and continues to return only the existing JSON payload on `stdout`. + +The recommended end-user experience is a short start message followed by one progress line for each accepted batch, in the existing fixed stream order. Each line names the stream, cumulative rows uploaded, and the current server cursor; empty streams still receive a concise no-new-rows status. The existing final text summary remains the command payload on `stdout`, while live progress goes to `stderr` so redirects and pipes remain safe. + +This extends the progress lifecycle with explicit start and end timestamps for one text-mode `sce trace sync` invocation. The start timestamp is emitted before the first control-plane request and the end timestamp is emitted after the invocation reaches a terminal success or failure; JSON output and the final report schema remain unchanged. + +## Acceptance criteria + +- [x] AC1: Text-mode `sce trace sync` emits live, human-readable progress to `stderr` while synchronization is underway, including the active stream and cumulative upload/cursor information for accepted batches, without waiting for the final report. + - Validate: `cli/src/services/trace` progress tests capture the injected progress sink and assert event order and batch values for a multi-batch sync. +- [x] AC2: Text-mode progress is deterministic and complete for all four streams: streams are reported in `messages`, `parts`, `diff_traces`, `agent_traces` order, and an empty stream reports that no rows were uploaded rather than disappearing. + - Validate: targeted sync progress test with populated and empty streams asserts the exact rendered progress lines/events. +- [x] AC3: JSON-mode `sce trace sync --format json` emits no human progress and preserves the existing JSON-only `stdout` contract and schema. + - Validate: command/render test runs the JSON path with a recording progress sink and asserts it remains empty while the parsed stdout payload matches the existing `render_sync` shape. +- [x] AC4: Progress reporting does not change sync correctness or persistence invariants: cursor advancement, reconciliation behavior, final text/JSON reports, and the absence of local sync state remain unchanged. + - Validate: existing `trace::sync` reconciliation/incremental tests and the focused progress tests pass. +- [x] AC5: Text-mode `sce trace sync` emits a start timestamp before its first control-plane request and an end timestamp after its terminal success or failure, with deterministic ordering and an unambiguous UTC representation. + - Validate: focused command tests with an injected clock and recording stderr sink assert start-before-request, end-after-terminal-result, and success/failure event ordering. +- [x] AC6: JSON-mode `sce trace sync --format json` emits neither lifecycle timestamp nor other human progress text and preserves the existing stdout JSON payload exactly. + - Validate: the JSON command test captures stderr and parses stdout, asserting an empty progress sink and the existing `render_sync` shape. + +### Full validation + +- `nix flake check` +- `nix run .#pkl-check-generated` + +### Context sync + +- `context/cli/trace-command.md` — document text-mode live progress, its `stderr` destination, lifecycle timestamps, and the unchanged JSON contract. +- `context/cli/agent-trace-sync-command.md` — document progress and request lifecycle timestamps as presentation behavior without changing the local-to-control-plane sync architecture. +- `context/sce/cli-stdout-stderr-contract.md` — record that live human-readable progress and lifecycle timestamps are emitted on `stderr` while command payloads remain on `stdout`. + +## Constraints and non-goals + +- **In scope:** `cli/src/services/trace/sync.rs`, `cli/src/services/trace/command.rs`, the text-mode progress sink/event seam and focused tests, plus the three context documents listed under Context sync. +- **Out of scope:** JSON schema changes, per-row payload dumps, progress bars or terminal cursor control, background/parallel stream synchronization, local cursors or any other persisted progress state, and changes to the control-plane protocol or reconciliation algorithm. +- **Constraints:** preserve the fixed stream order and existing final renderers; use an injectable in-memory sink in tests; send live progress only to `stderr`; do not leak credentials, raw server responses, or local database rows in progress output. +- **Non-goal:** redesigning the final concise sync report or adding progress fields to machine-readable JSON. + +## Assumptions + +- Progress is most useful at accepted-batch granularity: it gives feedback during large uploads without dumping individual rows or requiring terminal-specific redraw behavior. +- The production text reporter writes plain deterministic lines to `stderr`; it does not use carriage returns, spinners, or a TTY-only progress bar, so redirected human-readable output remains understandable. +- JSON mode has no progress side channel. This keeps `--format json` suitable for callers that expect no human text and avoids changing its established payload contract. +- “Request” means one `sce trace sync` invocation, not each individual HTTP batch request; the timestamps use UTC RFC3339 text and are supplied through an injectable clock so tests do not depend on wall-clock timing. +- A terminal end timestamp is reported for both successful and failed text-mode invocations, while preserving the existing classified error returned to the app. + +## Task stack + +- [x] T01: `Add injectable per-batch sync progress events` (status:complete) + - Task ID: T01 + - Goal: Extend the existing trace-sync orchestration with a typed, testable progress callback/sink that reports sync start, accepted-batch progress, and stream completion without changing cursor, reconciliation, or report behavior. + - Boundaries (in/out of scope): In — `cli/src/services/trace/sync.rs` progress event/sink types, callbacks at the existing four-stream and accepted-batch boundaries, and focused in-memory tests covering multi-batch, empty-stream, and fixed-order events. Out — production `stderr` formatting, CLI format selection, JSON behavior, and durable context edits. + - Dependencies: none + - Done when: callers can observe deterministic progress events as each batch is accepted, empty streams produce an explicit completion event, the four streams retain their existing order, and all existing sync/reconciliation tests still pass. + - Implementation evidence: Added typed `SyncProgressEvent` and injectable `SyncProgressSink` APIs with no-op compatibility wrappers; emitted start, validated accepted-batch, and stream-completion events through the existing fixed-order orchestration; added an in-memory sink test covering 1,001 rows across three batches and three empty streams. + - Verification notes (commands or checks): `nix build .#checks.x86_64-linux.cli-tests` passed; `nix build .#checks.x86_64-linux.cli-clippy` passed; `nix build .#checks.x86_64-linux.cli-fmt` passed; focused `services::trace::sync::tests` passed (6 tests). + +- [x] T02: `Wire text-only stderr progress into trace sync` (status:complete) + - Task ID: T02 + - Goal: Connect the progress seam to `TraceCommand` so text mode emits concise human-readable start/batch/completion lines on `stderr`, while JSON mode uses a no-op sink and preserves the existing final payload on `stdout`; document the resulting stream and sync presentation contract. + - Boundaries (in/out of scope): In — `cli/src/services/trace/command.rs` production reporter and format gating, exact progress-line rendering/tests, and updates to `context/cli/trace-command.md`, `context/cli/agent-trace-sync-command.md`, and `context/sce/cli-stdout-stderr-contract.md`. Out — changes to JSON fields, final report layout, sync protocol/reconciliation, progress bars, and local persistence. + - Dependencies: T01 + - Done when: text-mode execution emits the recommended deterministic progress lines incrementally to `stderr`; JSON-mode execution emits none and retains the current JSON shape; focused command/render tests and documentation reflect the behavior. + - Implementation evidence: Added an app-level stderr writer handoff for trace commands, a deterministic flushed text progress reporter for start, accepted-batch, and stream-completion events, and format gating that supplies a no-op sink for JSON. Documented the stderr progress and unchanged stdout/JSON contracts in the three requested context files. + - Verification notes (commands or checks): focused `services::trace::command` test passed (1 test); focused `services::trace::sync` tests passed (6 tests); `nix build .#checks.x86_64-linux.cli-tests` passed; `nix build .#checks.x86_64-linux.cli-clippy` passed; `nix build .#checks.x86_64-linux.cli-fmt` passed + +- [x] T03: `Restore the recorded text-progress implementation against current code` (status:complete) + - Task ID: T03 + - Goal: Bring the current trace-sync implementation back to the behavior recorded as complete in T01/T02: injectable typed progress events, deterministic text-only stderr reporting, fixed stream order, explicit empty-stream completion, and a no-op JSON path. + - Boundaries (in/out of scope): In — `cli/src/services/trace/sync.rs`, `cli/src/services/trace/command.rs`, focused progress tests, and the three context documents listed under Context sync. Out — lifecycle timestamps, final report fields, control-plane protocol/reconciliation, and local persistence. + - Dependencies: T02 + - Done when: the current code exposes and exercises the recorded progress seam and text/JSON format gating, with tests proving multi-batch, empty-stream, fixed-order, and JSON-no-progress behavior; the context documents agree with the implementation. + - Implementation evidence: Restored typed `SyncProgressEvent`/`SyncProgressSink` APIs with no-op and callback-compatible sinks, emitted validated accepted-batch and fixed-order stream-completion events, wired flushed deterministic text progress to the app-owned `stderr`, and kept JSON on the no-op path. Added focused multi-batch/empty-stream event coverage and deterministic reporter assertions; synchronized the three requested context documents. + - Verification notes (commands or checks): `nix develop -c ./scripts/run-cli-cargo.sh test --manifest-path cli/Cargo.toml services::trace::` passed (31 tests); `nix develop -c ./scripts/run-cli-cargo.sh check --manifest-path cli/Cargo.toml` passed; `nix develop -c sh -c 'cd cli && cargo fmt'` passed. + +- [x] T04: `Add text-mode request lifecycle timestamps` (status:complete) + - Task ID: T04 + - Goal: Emit an injected-clock UTC RFC3339 start timestamp before the first sync request and an end timestamp after successful or failed terminal completion, through the existing text progress reporter only. + - Boundaries (in/out of scope): In — lifecycle progress events/reporter wiring in `cli/src/services/trace/sync.rs` and `cli/src/services/trace/command.rs`, deterministic success/failure tests, and timestamp wording in the three context documents listed under Context sync. Out — JSON fields or human progress in JSON mode, final report layout, batch protocol/reconciliation behavior, terminal UI controls, and durable sync state. + - Dependencies: T03 + - Done when: text-mode output records start-before-request and end-after-terminal-result with deterministic event ordering and parseable UTC timestamps; JSON emits no timestamp/progress text and retains the existing payload; failure classification and sync persistence invariants are unchanged. + - Implementation evidence: Added injectable UTC progress clocks and started/finished lifecycle events around the full sync result, rendered lifecycle timestamps only through the text stderr reporter, preserved the no-op JSON sink, and added deterministic success/failure event coverage plus timestamp rendering assertions. Documented lifecycle timestamp behavior in the three requested context files. + - Verification notes (commands or checks): `nix develop -c ./scripts/run-cli-cargo.sh test --manifest-path cli/Cargo.toml services::trace::` passed (32 tests); `nix develop -c ./scripts/run-cli-cargo.sh check --manifest-path cli/Cargo.toml` passed; `nix build .#checks.x86_64-linux.cli-tests` passed; `nix build .#checks.x86_64-linux.cli-clippy` passed; `nix build .#checks.x86_64-linux.cli-fmt` passed; `git diff --check` passed. + +## Open questions + +None. The user constrained the change to human-readable text mode; per-accepted-batch, deterministic `stderr` lines are the recommended end-user behavior and are recorded as assumptions rather than additional scope questions. + +## Validation Report + +**Status:** validated +**Date:** 2026-08-13 + +### Commands run + +- `nix flake check` -> exit 0 (flake evaluation and available checks passed) +- `nix run .#pkl-check-generated` -> exit 0 (ephemeral generated-output parity passed) +- `nix develop -c ./scripts/run-cli-cargo.sh test --manifest-path cli/Cargo.toml services::trace::` -> exit 0 (32 focused trace tests passed) +- `nix develop -c ./scripts/run-cli-cargo.sh test --manifest-path cli/Cargo.toml services::trace::command::tests::progress_reporter_writes_deterministic_text_lines_and_flushes_each_event -- --exact` -> exit 0 (focused reporter test passed) +- `git diff --check` -> exit 0 (no whitespace errors) + +### Scaffolding removed + +- None. + +### Success-criteria verification + +- [x] AC1: Text-mode progress is emitted through the injected sink at accepted-batch boundaries; the multi-batch progress test passed. +- [x] AC2: The focused progress test passed with cumulative batch values, fixed four-stream order, and explicit empty-stream completion events. +- [x] AC3: The JSON renderer shape test passed; the command's JSON branch uses `NoopSyncProgressSink`, preserving the JSON-only payload path. +- [x] AC4: Focused trace tests passed, including incremental sync, reconciliation, final render shape, and the no-local-sync-state assertion. +- [x] AC5: Focused trace tests passed for injected UTC timestamps, start/end event order, and terminal failure completion; the reporter rendering test passed. +- [x] AC6: The JSON renderer shape test passed and the command's JSON branch uses the no-op sink, so lifecycle/progress text is not emitted. + +### Failed checks and follow-ups + +- None. + +### Residual risks + +- None identified. diff --git a/context/sce/agent-trace-export-readers.md b/context/sce/agent-trace-export-readers.md index 0e521fdd..f59a1e24 100644 --- a/context/sce/agent-trace-export-readers.md +++ b/context/sce/agent-trace-export-readers.md @@ -44,7 +44,7 @@ against `messages`, `parts`, `diff_traces`, and `agent_traces` respectively (`re Every call validates, before executing any query: - `cursor >= 0` -- `1 <= limit <= AGENT_TRACE_EXPORT_BATCH_SIZE` (500) +- `1 <= limit <= AGENT_TRACE_EXPORT_BATCH_SIZE` (100) and validates, per returned row before returning: diff --git a/context/sce/cli-stdout-stderr-contract.md b/context/sce/cli-stdout-stderr-contract.md index 04d59ebe..9459fbd4 100644 --- a/context/sce/cli-stdout-stderr-contract.md +++ b/context/sce/cli-stdout-stderr-contract.md @@ -26,3 +26,6 @@ See also: `context/sce/cli-error-code-taxonomy.md` for the canonical error-code - Stream routing is centralized in one app-level path to avoid per-command stream drift. - Exit code class mapping remains unchanged (`parse`, `validation`, `runtime`, `dependency`). - Observability lifecycle logs remain on `stderr` by contract and are independent from command payload output. +- Text-mode `sce trace sync` emits deterministic live start, cumulative accepted-batch, and stream-completion progress lines on `stderr`; the start line carries a UTC RFC3339 timestamp before the first sync request, and a terminal end timestamp follows success or failure. Empty streams report no new rows. JSON-mode sync emits no progress or lifecycle timestamp text and keeps its existing JSON-only payload on `stdout`. + +The durable trace-sync stream choice is recorded in [Trace-sync progress stream contract](../decisions/2026-08-13-trace-sync-progress-stream-contract.md). From 6c286c04dc2f782ebb776b69c9a5a13ea9478719 Mon Sep 17 00:00:00 2001 From: David Abram Date: Thu, 13 Aug 2026 16:01:51 +0200 Subject: [PATCH 2/2] trace: Run Agent Trace sync streams concurrently Start all four ingestion streams concurrently after one authoritative state fetch while preserving sequential batches and cursor-safe reconciliation within each stream. Coalesce concurrent token refreshes and add overlap/order regression coverage with updated sync documentation. Plan: agent-trace-sync-concurrency Task: T01, T02, T03 Co-authored-by: SCE --- cli/Cargo.toml | 2 +- .../agent_trace_sync/control_plane.rs | 154 +++++- cli/src/services/agent_trace_sync/mod.rs | 197 ++++--- .../agent_trace_sync/test_http_server.rs | 277 ++++++++++ cli/src/services/trace/sync.rs | 486 +++++++++++++----- context/architecture.md | 2 +- context/cli/agent-trace-sync-command.md | 8 +- context/cli/trace-command.md | 2 +- context/glossary.md | 1 + context/overview.md | 2 +- context/plans/agent-trace-sync-concurrency.md | 114 ++++ 11 files changed, 1000 insertions(+), 245 deletions(-) create mode 100644 context/plans/agent-trace-sync-concurrency.md diff --git a/cli/Cargo.toml b/cli/Cargo.toml index 941f5970..06aa4a3f 100644 --- a/cli/Cargo.toml +++ b/cli/Cargo.toml @@ -42,7 +42,7 @@ reqwest = { version = "0.13", default-features = false, features = ["json", "for serde = { version = "1", features = ["derive"] } serde_json = "1" sha2 = "0.11" -tokio = { version = "1", default-features = false, features = ["rt", "io-util", "time"] } +tokio = { version = "1", default-features = false, features = ["rt", "io-util", "sync", "time"] } tracing = "0.1" uuid = { version = "1", features = ["v4", "v7"] } diff --git a/cli/src/services/agent_trace_sync/control_plane.rs b/cli/src/services/agent_trace_sync/control_plane.rs index 4c91f0c1..b56b1c6e 100644 --- a/cli/src/services/agent_trace_sync/control_plane.rs +++ b/cli/src/services/agent_trace_sync/control_plane.rs @@ -231,6 +231,7 @@ pub struct AuthenticatedControlPlaneClient { workos_api_base_url: String, workos_client_id: String, credential_store: Arc, + refresh_lock: Arc>, } impl AuthenticatedControlPlaneClient { @@ -262,6 +263,7 @@ impl AuthenticatedControlPlaneClient { workos_api_base_url: workos_api_base_url.into(), workos_client_id: workos_client_id.into(), credential_store: Arc::from(credential_store), + refresh_lock: Arc::new(tokio::sync::Mutex::new(())), } } @@ -379,7 +381,7 @@ impl AuthenticatedControlPlaneClient { return Ok(response); } - let refreshed_token = self.force_refresh_access_token().await?; + let refreshed_token = self.force_refresh_access_token(&token).await?; let retried = build(&refreshed_token) .send() .await @@ -408,25 +410,40 @@ impl AuthenticatedControlPlaneClient { return Ok(stored.access_token); } - let token = auth::renew_stored_token_from_refresh_token( - &self.http, - &self.workos_api_base_url, - &self.workos_client_id, - &stored.refresh_token, - ) - .await?; - self.save_credentials(&token).await?; + let _refresh_guard = self.refresh_lock.lock().await; + let stored = self + .load_credentials() + .await? + .ok_or(ControlPlaneError::MissingCredentials)?; - Ok(token.access_token) + if !auth::is_stored_token_expired(&stored)? { + return Ok(stored.access_token); + } + + self.refresh_and_save(&stored).await } - /// Unconditionally refreshes the stored token via its refresh token and - /// saves the result, used for the unexpected-`401` retry path. - async fn force_refresh_access_token(&self) -> Result { + /// Refreshes the stored token while holding the client-wide single-flight + /// guard. Callers that observed the same rejected token can reuse a token + /// saved by an earlier caller instead of issuing another refresh. + async fn force_refresh_access_token( + &self, + rejected_access_token: &str, + ) -> Result { + let _refresh_guard = self.refresh_lock.lock().await; let stored = self .load_credentials() .await? .ok_or(ControlPlaneError::MissingCredentials)?; + + if stored.access_token != rejected_access_token { + return Ok(stored.access_token); + } + + self.refresh_and_save(&stored).await + } + + async fn refresh_and_save(&self, stored: &StoredTokens) -> Result { let token = auth::renew_stored_token_from_refresh_token( &self.http, &self.workos_api_base_url, @@ -554,8 +571,10 @@ where #[cfg(test)] mod tests { - use std::sync::{Arc, Mutex}; - use std::time::{SystemTime, UNIX_EPOCH}; + use std::sync::atomic::{AtomicUsize, Ordering}; + use std::sync::{Arc, Barrier, Mutex}; + use std::thread; + use std::time::{Duration, SystemTime, UNIX_EPOCH}; use super::*; use crate::services::agent_trace_db::MessageRole; @@ -912,6 +931,54 @@ mod tests { } } + #[derive(Clone)] + struct ConcurrentCredentialStore { + tokens: Arc>>, + initial_loads: Arc, + initial_load_barrier: Arc, + save_calls: Arc>>, + } + + impl ConcurrentCredentialStore { + fn with_tokens(tokens: StoredTokens) -> Self { + Self { + tokens: Arc::new(Mutex::new(Some(tokens))), + initial_loads: Arc::new(AtomicUsize::new(0)), + initial_load_barrier: Arc::new(Barrier::new(4)), + save_calls: Arc::new(Mutex::new(Vec::new())), + } + } + + fn save_call_count(&self) -> usize { + self.save_calls.lock().unwrap().len() + } + } + + impl CredentialStore for ConcurrentCredentialStore { + fn load(&self) -> Result, ControlPlaneError> { + let load_number = self.initial_loads.fetch_add(1, Ordering::SeqCst); + if load_number < 4 { + thread::sleep(Duration::from_millis(10)); + self.initial_load_barrier.wait(); + } + Ok(self.tokens.lock().unwrap().clone()) + } + + fn save(&self, token: &TokenResponse) -> Result { + self.save_calls.lock().unwrap().push(token.clone()); + let stored = StoredTokens { + access_token: token.access_token.clone(), + token_type: token.token_type.clone(), + expires_in: token.expires_in, + refresh_token: token.refresh_token.clone(), + scope: token.scope.clone(), + stored_at_unix_seconds: now_unix_seconds(), + }; + *self.tokens.lock().unwrap() = Some(stored.clone()); + Ok(stored) + } + } + struct RuntimeCheckingCredentialStore; impl CredentialStore for RuntimeCheckingCredentialStore { @@ -1048,6 +1115,63 @@ mod tests { ); } + #[test] + fn concurrent_expired_tokens_share_one_refresh_and_save() { + let server = TestHttpServer::start(); + server.queue_response(CannedResponse::json( + 200, + &token_response_json("refreshed-token"), + )); + for _ in 0..4 { + server.queue_response(CannedResponse::json(200, &state_response_json())); + } + let store = ConcurrentCredentialStore::with_tokens(expired_stored_tokens("stale-token")); + let store_handle = store.clone(); + let client = Arc::new(AuthenticatedControlPlaneClient::with_credential_store( + test_http_client(), + server.base_url.clone(), + server.base_url.clone(), + "test-client-id", + Box::new(store), + )); + let results = block_on(async { + let handles = (0..4) + .map(|_| { + let client = Arc::clone(&client); + tokio::spawn( + async move { client.ingestion_state(&sample_state_request()).await }, + ) + }) + .collect::>(); + let mut results = Vec::new(); + for handle in handles { + results.push(handle.await.expect("concurrent state request task")); + } + results + }); + + assert!(results.iter().all(Result::is_ok)); + assert_eq!(store_handle.save_call_count(), 1); + let requests = server.captured_requests(); + assert_eq!(requests.len(), 5); + assert_eq!( + requests + .iter() + .filter(|request| request.path == "/oauth2/token") + .count(), + 1 + ); + let state_requests = requests + .iter() + .filter(|request| request.path == "/agent-trace/ingestion/state") + .collect::>(); + assert_eq!(state_requests.len(), 4); + assert!(state_requests.iter().all(|request| { + request.headers.get("authorization").map(String::as_str) + == Some("Bearer refreshed-token") + })); + } + #[test] fn unexpected_401_refreshes_once_and_retries_once_on_success() { let server = TestHttpServer::start(); diff --git a/cli/src/services/agent_trace_sync/mod.rs b/cli/src/services/agent_trace_sync/mod.rs index bd89534c..18cc3861 100644 --- a/cli/src/services/agent_trace_sync/mod.rs +++ b/cli/src/services/agent_trace_sync/mod.rs @@ -7,6 +7,8 @@ pub mod control_plane; pub(crate) mod test_http_server; use std::fmt; +use std::future::Future; +use std::pin::Pin; use crate::services::agent_trace_export::{ AgentTraceAgentTraceExportRow, AgentTraceDiffTraceExportRow, AgentTraceMessageExportRow, @@ -121,7 +123,9 @@ pub struct StreamSyncOutcome { /// refreshed value: if it advanced, the next read naturally skips the /// already-accepted rows; if unchanged, the same rows are re-read and /// resent. Both cases share one bounded reconciliation counter. -pub fn sync_stream( +pub type SyncFuture<'a, Output> = Pin + 'a>>; + +pub async fn sync_stream<'a, T, ReadFn, IngestFn, RefreshFn>( initial_cursor: i64, batch_limit: usize, mut read_after: ReadFn, @@ -129,10 +133,10 @@ pub fn sync_stream( mut refresh_cursor: RefreshFn, ) -> Result where - T: AgentTraceExportRow, - ReadFn: FnMut(i64, usize) -> Result, StreamSyncError>, - IngestFn: FnMut(i64, &[T]) -> BatchAttemptOutcome, - RefreshFn: FnMut() -> Result, + T: AgentTraceExportRow + 'a, + ReadFn: FnMut(i64, usize) -> SyncFuture<'a, Result, StreamSyncError>>, + IngestFn: for<'rows> FnMut(i64, &'rows [T]) -> SyncFuture<'a, BatchAttemptOutcome>, + RefreshFn: FnMut() -> SyncFuture<'a, Result>, { let mut cursor = initial_cursor; let mut uploaded = 0usize; @@ -140,12 +144,12 @@ where let mut reconciliation_attempts = 0u32; loop { - let rows = read_after(cursor, batch_limit)?; + let rows = read_after(cursor, batch_limit).await?; if rows.is_empty() { break; } - match ingest_batch(cursor, &rows) { + match ingest_batch(cursor, &rows).await { BatchAttemptOutcome::Accepted { accepted, cursor: reported_cursor, @@ -173,7 +177,7 @@ where return Err(StreamSyncError::DidNotConverge); } - cursor = refresh_cursor()?; + cursor = refresh_cursor().await?; } } } @@ -189,10 +193,23 @@ where #[cfg(test)] mod tests { use std::cell::RefCell; + use std::future::Future; use super::*; use crate::services::agent_trace_db::MessageRole; + fn block_on(future: F) -> F::Output { + tokio::runtime::Builder::new_current_thread() + .enable_time() + .build() + .expect("build test runtime") + .block_on(future) + } + + fn ready(value: T) -> SyncFuture<'static, T> { + Box::pin(std::future::ready(value)) + } + fn row(source_row_id: i64) -> AgentTraceMessageExportRow { AgentTraceMessageExportRow { source_row_id, @@ -203,9 +220,6 @@ mod tests { } } - /// In-memory local store: rows never disappear, only the caller-visible - /// server-accepted cursor advances, mirroring how the real reader and - /// control plane are independent sources of truth. struct FakeLocalRows { rows: Vec, } @@ -231,20 +245,19 @@ mod tests { fn empty_database_makes_no_batch_calls() { let local = FakeLocalRows::new(0); let batch_calls = RefCell::new(0usize); - - let outcome = sync_stream( + let outcome = block_on(sync_stream( 0, 500, - |cursor, limit| Ok(local.after(cursor, limit)), + |cursor, limit| ready(Ok(local.after(cursor, limit))), |_cursor, rows: &[AgentTraceMessageExportRow]| { *batch_calls.borrow_mut() += 1; - BatchAttemptOutcome::Accepted { + ready(BatchAttemptOutcome::Accepted { accepted: rows.len(), cursor: rows.last().map_or(0, |row| row.source_row_id), - } + }) }, || panic!("refresh should not be called when there is nothing to reconcile"), - ) + )) .unwrap(); assert_eq!(*batch_calls.borrow(), 0); @@ -263,55 +276,47 @@ mod tests { fn one_batch_uploads_all_rows_and_advances_cursor() { let local = FakeLocalRows::new(3); let batch_calls = RefCell::new(0usize); - - let outcome = sync_stream( + let outcome = block_on(sync_stream( 0, 500, - |cursor, limit| Ok(local.after(cursor, limit)), + |cursor, limit| ready(Ok(local.after(cursor, limit))), |_cursor, rows: &[AgentTraceMessageExportRow]| { *batch_calls.borrow_mut() += 1; - BatchAttemptOutcome::Accepted { + ready(BatchAttemptOutcome::Accepted { accepted: rows.len(), cursor: rows.last().unwrap().source_row_id, - } + }) }, || panic!("refresh should not be called on an all-success run"), - ) + )) .unwrap(); assert_eq!(*batch_calls.borrow(), 1); - assert_eq!( - outcome, - StreamSyncOutcome { - uploaded: 3, - initial_cursor: 0, - final_cursor: 3, - batches: 1, - } - ); + assert_eq!(outcome.uploaded, 3); + assert_eq!(outcome.final_cursor, 3); + assert_eq!(outcome.batches, 1); } #[test] fn more_than_five_hundred_rows_span_multiple_bounded_batches() { let local = FakeLocalRows::new(1_100); let batch_sizes = RefCell::new(Vec::new()); - - let outcome = sync_stream( + let outcome = block_on(sync_stream( 0, 500, |cursor, limit| { assert!(limit <= 500); - Ok(local.after(cursor, limit)) + ready(Ok(local.after(cursor, limit))) }, |_cursor, rows: &[AgentTraceMessageExportRow]| { batch_sizes.borrow_mut().push(rows.len()); - BatchAttemptOutcome::Accepted { + ready(BatchAttemptOutcome::Accepted { accepted: rows.len(), cursor: rows.last().unwrap().source_row_id, - } + }) }, || panic!("refresh should not be called on an all-success run"), - ) + )) .unwrap(); assert_eq!(*batch_sizes.borrow(), vec![500, 500, 100]); @@ -325,61 +330,56 @@ mod tests { let local = FakeLocalRows { rows: vec![row(2), row(5), row(9)], }; - - let outcome = sync_stream( + let outcome = block_on(sync_stream( 0, 500, - |cursor, limit| Ok(local.after(cursor, limit)), - |_cursor, rows: &[AgentTraceMessageExportRow]| BatchAttemptOutcome::Accepted { - accepted: rows.len(), - cursor: rows.last().unwrap().source_row_id, + |cursor, limit| ready(Ok(local.after(cursor, limit))), + |_cursor, rows: &[AgentTraceMessageExportRow]| { + ready(BatchAttemptOutcome::Accepted { + accepted: rows.len(), + cursor: rows.last().unwrap().source_row_id, + }) }, || panic!("refresh should not be called on an all-success run"), - ) + )) .unwrap(); assert_eq!(outcome.uploaded, 3); assert_eq!(outcome.final_cursor, 9); - let uploaded_as_cursor_delta = - i64::try_from(outcome.uploaded).expect("uploaded count fits in i64 for this test"); - assert_ne!( - outcome.final_cursor, - outcome.initial_cursor + uploaded_as_cursor_delta - ); + assert_ne!(outcome.final_cursor, outcome.initial_cursor + 3); } #[test] fn conflict_resends_only_the_unsent_tail() { - // Mirrors the plan's worked example: state=10, local rows 11-13, the - // first batch 409s, refreshed state=12, only row 13 is resent with - // expected_cursor=12. let local = FakeLocalRows { rows: vec![row(11), row(12), row(13)], }; let attempts: RefCell)>> = RefCell::new(Vec::new()); - - let outcome = sync_stream( + let outcome = block_on(sync_stream( 10, 500, - |cursor, limit| Ok(local.after(cursor, limit)), + |cursor, limit| ready(Ok(local.after(cursor, limit))), |cursor, rows: &[AgentTraceMessageExportRow]| { - let ids: Vec = rows.iter().map(|row| row.source_row_id).collect(); + let ids = rows.iter().map(|row| row.source_row_id).collect(); attempts.borrow_mut().push((cursor, ids)); - if attempts.borrow().len() == 1 { + let result = if attempts.borrow().len() == 1 { BatchAttemptOutcome::Conflict } else { BatchAttemptOutcome::Accepted { accepted: rows.len(), cursor: rows.last().unwrap().source_row_id, } - } + }; + ready(result) }, - || Ok(12), - ) + || ready(Ok(12)), + )) .unwrap(); - let attempts = attempts.into_inner(); - assert_eq!(attempts, vec![(10, vec![11, 12, 13]), (12, vec![13])]); + assert_eq!( + attempts.into_inner(), + vec![(10, vec![11, 12, 13]), (12, vec![13])] + ); assert_eq!(outcome.uploaded, 1); assert_eq!(outcome.final_cursor, 13); } @@ -388,32 +388,28 @@ mod tests { fn ambiguous_failure_with_advanced_refresh_does_not_resend() { let local = FakeLocalRows::new(3); let attempts: RefCell>> = RefCell::new(Vec::new()); - - let outcome = sync_stream( + let outcome = block_on(sync_stream( 0, 500, - |cursor, limit| Ok(local.after(cursor, limit)), + |cursor, limit| ready(Ok(local.after(cursor, limit))), |_cursor, rows: &[AgentTraceMessageExportRow]| { - let ids: Vec = rows.iter().map(|row| row.source_row_id).collect(); - let is_first = attempts.borrow().is_empty(); + let ids = rows.iter().map(|row| row.source_row_id).collect(); + let first = attempts.borrow().is_empty(); attempts.borrow_mut().push(ids); - if is_first { + ready(if first { BatchAttemptOutcome::Ambiguous } else { BatchAttemptOutcome::Accepted { accepted: rows.len(), cursor: rows.last().unwrap().source_row_id, } - } + }) }, - // The control plane had already committed the batch server-side - // despite the ambiguous response; /state now reflects it. - || Ok(3), - ) + || ready(Ok(3)), + )) .unwrap(); - let attempts = attempts.into_inner(); - assert_eq!(attempts, vec![vec![1, 2, 3]]); + assert_eq!(attempts.into_inner(), vec![vec![1, 2, 3]]); assert_eq!(outcome.uploaded, 0); assert_eq!(outcome.final_cursor, 3); } @@ -422,31 +418,28 @@ mod tests { fn ambiguous_failure_with_unchanged_refresh_resends_once() { let local = FakeLocalRows::new(3); let attempts: RefCell>> = RefCell::new(Vec::new()); - - let outcome = sync_stream( + let outcome = block_on(sync_stream( 0, 500, - |cursor, limit| Ok(local.after(cursor, limit)), + |cursor, limit| ready(Ok(local.after(cursor, limit))), |_cursor, rows: &[AgentTraceMessageExportRow]| { - let ids: Vec = rows.iter().map(|row| row.source_row_id).collect(); - let is_first = attempts.borrow().is_empty(); + let ids = rows.iter().map(|row| row.source_row_id).collect(); + let first = attempts.borrow().is_empty(); attempts.borrow_mut().push(ids); - if is_first { + ready(if first { BatchAttemptOutcome::Ambiguous } else { BatchAttemptOutcome::Accepted { accepted: rows.len(), cursor: rows.last().unwrap().source_row_id, } - } + }) }, - // /state confirms nothing was actually committed. - || Ok(0), - ) + || ready(Ok(0)), + )) .unwrap(); - let attempts = attempts.into_inner(); - assert_eq!(attempts, vec![vec![1, 2, 3], vec![1, 2, 3]]); + assert_eq!(attempts.into_inner(), vec![vec![1, 2, 3], vec![1, 2, 3]]); assert_eq!(outcome.uploaded, 3); assert_eq!(outcome.final_cursor, 3); } @@ -454,14 +447,13 @@ mod tests { #[test] fn reconciliation_bound_fails_with_did_not_converge() { let local = FakeLocalRows::new(3); - - let result = sync_stream( + let result = block_on(sync_stream( 0, 500, - |cursor, limit| Ok(local.after(cursor, limit)), - |_cursor, _rows: &[AgentTraceMessageExportRow]| BatchAttemptOutcome::Ambiguous, - || Ok(0), - ); + |cursor, limit| ready(Ok(local.after(cursor, limit))), + |_cursor, _rows: &[AgentTraceMessageExportRow]| ready(BatchAttemptOutcome::Ambiguous), + || ready(Ok(0)), + )); assert!(matches!(result, Err(StreamSyncError::DidNotConverge))); } @@ -469,17 +461,18 @@ mod tests { #[test] fn invalid_response_rejects_mismatched_accepted_and_cursor() { let local = FakeLocalRows::new(3); - - let result = sync_stream( + let result = block_on(sync_stream( 0, 500, - |cursor, limit| Ok(local.after(cursor, limit)), - |_cursor, _rows: &[AgentTraceMessageExportRow]| BatchAttemptOutcome::Accepted { - accepted: 2, - cursor: 99, + |cursor, limit| ready(Ok(local.after(cursor, limit))), + |_cursor, _rows: &[AgentTraceMessageExportRow]| { + ready(BatchAttemptOutcome::Accepted { + accepted: 2, + cursor: 99, + }) }, || panic!("refresh should not be called on an invalid response"), - ); + )); assert!(matches!(result, Err(StreamSyncError::InvalidResponse(_)))); } diff --git a/cli/src/services/agent_trace_sync/test_http_server.rs b/cli/src/services/agent_trace_sync/test_http_server.rs index b2a96b09..a5d92729 100644 --- a/cli/src/services/agent_trace_sync/test_http_server.rs +++ b/cli/src/services/agent_trace_sync/test_http_server.rs @@ -9,6 +9,7 @@ use std::io::{BufRead, BufReader, Read, Write}; use std::net::TcpListener; use std::sync::{Arc, Mutex}; use std::thread; +use std::time::Duration; #[derive(Clone, Debug)] pub struct CapturedRequest { @@ -98,6 +99,135 @@ impl TestHttpServer { } } +/// A concurrent test server for sync regressions. State responses are queued +/// independently from dynamically selected batch responses, allowing each +/// stream's expected cursor to determine the response it receives. +pub struct ConcurrentBatchTestServer { + pub base_url: String, + requests: Arc>>, + state_response: Arc>>, + batch_responses: Arc>>, + metrics: Arc>, +} + +#[derive(Clone, Debug, Default)] +struct ConcurrentBatchMetrics { + state_requests: usize, + in_flight: usize, + max_in_flight: usize, + in_flight_by_stream: HashMap, + max_in_flight_by_stream: HashMap, + expected_cursors_by_stream: HashMap>, +} + +impl ConcurrentBatchTestServer { + pub fn start(batch_delay: Duration) -> Self { + let listener = TcpListener::bind("127.0.0.1:0").expect("bind concurrent test http server"); + let addr = listener + .local_addr() + .expect("read concurrent test http server addr"); + + let requests: Arc>> = Arc::new(Mutex::new(Vec::new())); + let state_response = Arc::new(Mutex::new(None)); + let batch_responses = Arc::new(Mutex::new(HashMap::new())); + let metrics = Arc::new(Mutex::new(ConcurrentBatchMetrics::default())); + + let thread_requests = Arc::clone(&requests); + let thread_state_response = Arc::clone(&state_response); + let thread_batch_responses = Arc::clone(&batch_responses); + let thread_metrics = Arc::clone(&metrics); + thread::spawn(move || { + for stream in listener.incoming() { + let Ok(stream) = stream else { + continue; + }; + let requests = Arc::clone(&thread_requests); + let state_response = Arc::clone(&thread_state_response); + let batch_responses = Arc::clone(&thread_batch_responses); + let metrics = Arc::clone(&thread_metrics); + thread::spawn(move || { + handle_concurrent_connection( + stream, + &requests, + &state_response, + &batch_responses, + &metrics, + batch_delay, + ); + }); + } + }); + + Self { + base_url: format!("http://{addr}"), + requests, + state_response, + batch_responses, + metrics, + } + } + + pub fn queue_state_response(&self, response: CannedResponse) { + *self + .state_response + .lock() + .expect("concurrent test http server state response lock") = Some(response); + } + + pub fn queue_batch_response( + &self, + stream: impl Into, + expected_cursor: i64, + response: CannedResponse, + ) { + self.batch_responses + .lock() + .expect("concurrent test http server batch responses lock") + .insert((stream.into(), expected_cursor), response); + } + + pub fn captured_requests(&self) -> Vec { + self.requests + .lock() + .expect("concurrent test http server requests lock") + .clone() + } + + pub fn state_request_count(&self) -> usize { + self.metrics + .lock() + .expect("concurrent test http server metrics lock") + .state_requests + } + + pub fn max_in_flight(&self) -> usize { + self.metrics + .lock() + .expect("concurrent test http server metrics lock") + .max_in_flight + } + + pub fn max_in_flight_for(&self, stream: &str) -> usize { + self.metrics + .lock() + .expect("concurrent test http server metrics lock") + .max_in_flight_by_stream + .get(stream) + .copied() + .unwrap_or(0) + } + + pub fn expected_cursors_for(&self, stream: &str) -> Vec { + self.metrics + .lock() + .expect("concurrent test http server metrics lock") + .expected_cursors_by_stream + .get(stream) + .cloned() + .unwrap_or_default() + } +} + fn handle_connection( stream: std::net::TcpStream, requests: &Arc>>, @@ -171,6 +301,153 @@ fn handle_connection( let _ = stream.flush(); } +fn handle_concurrent_connection( + stream: std::net::TcpStream, + requests: &Arc>>, + state_response: &Arc>>, + batch_responses: &Arc>>, + metrics: &Arc>, + batch_delay: Duration, +) { + let Some(request) = read_request(&stream) else { + return; + }; + requests + .lock() + .expect("concurrent test http server requests lock") + .push(request.clone()); + + let response = match request.path.as_str() { + "/agent-trace/ingestion/state" => { + metrics + .lock() + .expect("concurrent test http server metrics lock") + .state_requests += 1; + state_response + .lock() + .expect("concurrent test http server state response lock") + .clone() + .unwrap_or_else(|| CannedResponse::text(500, "no state response queued")) + } + "/agent-trace/ingestion/batch" => { + let body: serde_json::Value = + serde_json::from_str(&request.body).unwrap_or_else(|_| serde_json::json!({})); + let stream = body + .get("stream") + .and_then(serde_json::Value::as_str) + .unwrap_or("unknown") + .to_string(); + let expected_cursor = body + .get("expectedCursor") + .and_then(serde_json::Value::as_i64) + .unwrap_or(i64::MIN); + + { + let mut metrics = metrics + .lock() + .expect("concurrent test http server metrics lock"); + metrics.in_flight += 1; + metrics.max_in_flight = metrics.max_in_flight.max(metrics.in_flight); + let stream_in_flight = { + let count = metrics + .in_flight_by_stream + .entry(stream.clone()) + .or_default(); + *count += 1; + *count + }; + let stream_max_in_flight = metrics + .max_in_flight_by_stream + .entry(stream.clone()) + .or_default(); + *stream_max_in_flight = (*stream_max_in_flight).max(stream_in_flight); + metrics + .expected_cursors_by_stream + .entry(stream.clone()) + .or_default() + .push(expected_cursor); + } + + thread::sleep(batch_delay); + let response = batch_responses + .lock() + .expect("concurrent test http server batch responses lock") + .get(&(stream.clone(), expected_cursor)) + .cloned() + .unwrap_or_else(|| CannedResponse::text(500, "no batch response queued")); + let mut metrics = metrics + .lock() + .expect("concurrent test http server metrics lock"); + metrics.in_flight -= 1; + if let Some(stream_in_flight) = metrics.in_flight_by_stream.get_mut(&stream) { + *stream_in_flight -= 1; + } + drop(metrics); + response + } + _ => CannedResponse::text(404, "unknown test route"), + }; + + write_response(stream, &response); +} + +fn read_request(stream: &std::net::TcpStream) -> Option { + let mut reader = BufReader::new(stream.try_clone().ok()?); + + let mut request_line = String::new(); + if reader.read_line(&mut request_line).unwrap_or(0) == 0 { + return None; + } + let mut parts = request_line.split_whitespace(); + let method = parts.next().unwrap_or_default().to_string(); + let path = parts.next().unwrap_or_default().to_string(); + + let mut headers = HashMap::new(); + let mut content_length = 0usize; + loop { + let mut line = String::new(); + if reader.read_line(&mut line).unwrap_or(0) == 0 { + break; + } + let trimmed = line.trim_end_matches(['\r', '\n']); + if trimmed.is_empty() { + break; + } + if let Some((name, value)) = trimmed.split_once(':') { + let name = name.trim().to_ascii_lowercase(); + let value = value.trim().to_string(); + if name == "content-length" { + content_length = value.parse().unwrap_or(0); + } + headers.insert(name, value); + } + } + + let mut body_bytes = vec![0u8; content_length]; + if content_length > 0 && reader.read_exact(&mut body_bytes).is_err() { + return None; + } + + Some(CapturedRequest { + method, + path, + headers, + body: String::from_utf8_lossy(&body_bytes).to_string(), + }) +} + +fn write_response(mut stream: std::net::TcpStream, canned: &CannedResponse) { + let response = format!( + "HTTP/1.1 {} {}\r\nContent-Type: application/json\r\nContent-Length: {}\r\nConnection: close\r\n\r\n{}", + canned.status, + status_reason(canned.status), + canned.body.len(), + canned.body, + ); + let _ = stream.write_all(response.as_bytes()); + let _ = stream.flush(); +} + fn status_reason(status: u16) -> &'static str { match status { 200 => "OK", diff --git a/cli/src/services/trace/sync.rs b/cli/src/services/trace/sync.rs index f84a9d13..28b1fe6e 100644 --- a/cli/src/services/trace/sync.rs +++ b/cli/src/services/trace/sync.rs @@ -9,8 +9,11 @@ use std::cell::RefCell; use std::fmt; +use std::future::{poll_fn, Future}; use std::path::Path; +use std::rc::Rc; use std::sync::OnceLock; +use std::task::Poll; use anyhow::Context; use chrono::{DateTime, SecondsFormat, Utc}; @@ -25,7 +28,7 @@ use crate::services::agent_trace_sync::control_plane::{ IngestionStream, }; use crate::services::agent_trace_sync::{ - sync_stream, AgentTraceExportRow, BatchAttemptOutcome, StreamSyncError, + sync_stream, AgentTraceExportRow, BatchAttemptOutcome, StreamSyncError, SyncFuture, }; use crate::services::auth; use crate::services::config; @@ -299,62 +302,98 @@ where let runtime = shared_runtime()?; let reader = AgentTraceExportReader::new(db); + runtime.block_on(run_sync_async( + repository_id, + source_instance_id, + &reader, + client, + progress, + )) +} + +async fn run_sync_async<'a, S>( + repository_id: &'a str, + source_instance_id: &'a str, + reader: &'a AgentTraceExportReader<'a>, + client: &'a AuthenticatedControlPlaneClient, + progress: &'a mut S, +) -> Result +where + S: SyncProgressSink + 'a, +{ let state_request = AgentTraceIngestionStateRequest { repository_id: repository_id.to_string(), source_instance_id: source_instance_id.to_string(), }; - let state = runtime - .block_on(client.ingestion_state(&state_request)) + let state = client + .ingestion_state(&state_request) + .await .map_err(TraceSyncError::ControlPlane)?; - - let messages = sync_one_stream( - runtime, - client, - repository_id, - source_instance_id, - IngestionStream::Messages, - state.cursors.messages, - "messages", - |cursor, limit| reader.read_messages_after(cursor, limit), - |request| runtime.block_on(client.ingest_messages(request)), - progress, - )?; - let parts = sync_one_stream( - runtime, - client, - repository_id, - source_instance_id, - IngestionStream::Parts, - state.cursors.parts, - "parts", - |cursor, limit| reader.read_parts_after(cursor, limit), - |request| runtime.block_on(client.ingest_parts(request)), - progress, - )?; - let diff_traces = sync_one_stream( - runtime, - client, - repository_id, - source_instance_id, - IngestionStream::DiffTraces, - state.cursors.diff_traces, - "diff_traces", - |cursor, limit| reader.read_diff_traces_after(cursor, limit), - |request| runtime.block_on(client.ingest_diff_traces(request)), - progress, - )?; - let agent_traces = sync_one_stream( - runtime, - client, - repository_id, - source_instance_id, - IngestionStream::AgentTraces, - state.cursors.agent_traces, - "agent_traces", - |cursor, limit| reader.read_agent_traces_after(cursor, limit), - |request| runtime.block_on(client.ingest_agent_traces(request)), - progress, - )?; + let progress = Rc::new(RefCell::new(progress)); + + let (messages, parts, diff_traces, agent_traces) = try_join_four( + sync_one_stream( + client, + repository_id, + source_instance_id, + IngestionStream::Messages, + state.cursors.messages, + "messages", + |cursor, limit| reader.read_messages_after(cursor, limit), + |request| Box::pin(async move { client.ingest_messages(&request).await }), + Rc::clone(&progress), + ), + sync_one_stream( + client, + repository_id, + source_instance_id, + IngestionStream::Parts, + state.cursors.parts, + "parts", + |cursor, limit| reader.read_parts_after(cursor, limit), + |request| Box::pin(async move { client.ingest_parts(&request).await }), + Rc::clone(&progress), + ), + sync_one_stream( + client, + repository_id, + source_instance_id, + IngestionStream::DiffTraces, + state.cursors.diff_traces, + "diff_traces", + |cursor, limit| reader.read_diff_traces_after(cursor, limit), + |request| Box::pin(async move { client.ingest_diff_traces(&request).await }), + Rc::clone(&progress), + ), + sync_one_stream( + client, + repository_id, + source_instance_id, + IngestionStream::AgentTraces, + state.cursors.agent_traces, + "agent_traces", + |cursor, limit| reader.read_agent_traces_after(cursor, limit), + |request| Box::pin(async move { client.ingest_agent_traces(&request).await }), + Rc::clone(&progress), + ), + ) + .await?; + + for (stream, report) in [ + ("messages", messages), + ("parts", parts), + ("diff_traces", diff_traces), + ("agent_traces", agent_traces), + ] { + progress + .borrow_mut() + .report(SyncProgressEvent::StreamCompleted { + stream, + uploaded: report.uploaded, + cursor: report.final_cursor, + batches: report.batches, + }); + } Ok(AgentTraceSyncReport { repository_id: repository_id.to_string(), @@ -368,41 +407,114 @@ where }) } +async fn try_join_four( + a: A, + b: B, + c: C, + d: D, +) -> Result<(OA, OB, OC, OD), E> +where + A: Future>, + B: Future>, + C: Future>, + D: Future>, +{ + let mut a = Box::pin(a); + let mut b = Box::pin(b); + let mut c = Box::pin(c); + let mut d = Box::pin(d); + let mut a_output = None; + let mut b_output = None; + let mut c_output = None; + let mut d_output = None; + + poll_fn(|context| { + if a_output.is_none() { + if let Poll::Ready(result) = a.as_mut().poll(context) { + a_output = Some(result?); + } + } + if b_output.is_none() { + if let Poll::Ready(result) = b.as_mut().poll(context) { + b_output = Some(result?); + } + } + if c_output.is_none() { + if let Poll::Ready(result) = c.as_mut().poll(context) { + c_output = Some(result?); + } + } + if d_output.is_none() { + if let Poll::Ready(result) = d.as_mut().poll(context) { + d_output = Some(result?); + } + } + + match ( + a_output.take(), + b_output.take(), + c_output.take(), + d_output.take(), + ) { + (Some(a), Some(b), Some(c), Some(d)) => Poll::Ready(Ok((a, b, c, d))), + (a, b, c, d) => { + a_output = a; + b_output = b; + c_output = c; + d_output = d; + Poll::Pending + } + } + }) + .await +} + /// Synchronizes one stream via the T04 engine. Genuine `409`/`5xx`/transport /// ambiguity reconciles through a real `/state` refetch; a terminal /// control-plane failure (missing/invalid auth, `400`, `403`) short-circuits /// the reconciliation closure with that failure instead of issuing another /// network call, so a `403` never mutates local state or retries. #[allow(clippy::too_many_arguments)] -fn sync_one_stream( - runtime: &Runtime, - client: &AuthenticatedControlPlaneClient, - repository_id: &str, - source_instance_id: &str, +async fn sync_one_stream<'a, T, ReadFn, IngestFn, S>( + client: &'a AuthenticatedControlPlaneClient, + repository_id: &'a str, + source_instance_id: &'a str, stream: IngestionStream, initial_cursor: i64, stream_label: &'static str, mut read_after: ReadFn, mut ingest: IngestFn, - progress: &mut impl SyncProgressSink, + progress: Rc>, ) -> Result where - T: AgentTraceExportRow + Clone, - ReadFn: FnMut(i64, usize) -> anyhow::Result>, + T: AgentTraceExportRow + Clone + 'a, + S: SyncProgressSink + 'a, + ReadFn: FnMut(i64, usize) -> anyhow::Result> + 'a, IngestFn: FnMut( - &AgentTraceIngestionBatchRequest, - ) -> Result, + AgentTraceIngestionBatchRequest, + ) + -> SyncFuture<'a, Result> + + 'a, { - let terminal: RefCell> = RefCell::new(None); - let uploaded = RefCell::new(0usize); + let terminal: Rc>> = Rc::new(RefCell::new(None)); + let uploaded = Rc::new(RefCell::new(0usize)); let outcome = sync_stream( initial_cursor, AGENT_TRACE_EXPORT_BATCH_SIZE, |cursor, limit| { - read_after(cursor, limit).map_err(|error| StreamSyncError::Read(format!("{error:#}"))) + let result = read_after(cursor, limit) + .map_err(|error| StreamSyncError::Read(format!("{error:#}"))); + Box::pin(std::future::ready(result)) }, |cursor, rows: &[T]| { + let terminal = Rc::clone(&terminal); + let uploaded = Rc::clone(&uploaded); + let row_count = rows.len(); + let last_row_id = rows + .last() + .expect("rows checked non-empty above") + .source_row_id(); let request = AgentTraceIngestionBatchRequest { repository_id: repository_id.to_string(), source_instance_id: source_instance_id.to_string(), @@ -410,68 +522,68 @@ where expected_cursor: cursor, rows: rows.to_vec(), }; - match ingest(&request) { - Ok(response) => { - let last_row_id = rows - .last() - .expect("rows checked non-empty above") - .source_row_id(); - if response.accepted == rows.len() && response.cursor == last_row_id { - *uploaded.borrow_mut() += rows.len(); - progress.report(SyncProgressEvent::BatchAccepted { - stream: stream_label, - batch_rows: rows.len(), - uploaded: *uploaded.borrow(), + let ingest_future = ingest(request); + let progress = Rc::clone(&progress); + Box::pin(async move { + match ingest_future.await { + Ok(response) => { + if response.accepted == row_count && response.cursor == last_row_id { + *uploaded.borrow_mut() += row_count; + progress + .borrow_mut() + .report(SyncProgressEvent::BatchAccepted { + stream: stream_label, + batch_rows: row_count, + uploaded: *uploaded.borrow(), + cursor: response.cursor, + }); + } + BatchAttemptOutcome::Accepted { + accepted: response.accepted, cursor: response.cursor, - }); + } } - BatchAttemptOutcome::Accepted { - accepted: response.accepted, - cursor: response.cursor, + Err(ControlPlaneError::Conflict(_)) => BatchAttemptOutcome::Conflict, + Err(error) if is_stream_terminal(&error) => { + *terminal.borrow_mut() = Some(error); + BatchAttemptOutcome::Ambiguous } + Err(_) => BatchAttemptOutcome::Ambiguous, } - Err(ControlPlaneError::Conflict(_)) => BatchAttemptOutcome::Conflict, - Err(error) if is_stream_terminal(&error) => { - *terminal.borrow_mut() = Some(error); - BatchAttemptOutcome::Ambiguous - } - Err(_) => BatchAttemptOutcome::Ambiguous, - } + }) }, || { if let Some(error) = terminal.borrow_mut().take() { - return Err(StreamSyncError::Refresh(error.to_string())); + return Box::pin(std::future::ready(Err(StreamSyncError::Refresh( + error.to_string(), + )))); } let state_request = AgentTraceIngestionStateRequest { repository_id: repository_id.to_string(), source_instance_id: source_instance_id.to_string(), }; - let response = runtime - .block_on(client.ingestion_state(&state_request)) - .map_err(|error| StreamSyncError::Refresh(error.to_string()))?; - Ok(cursor_for_stream(&response.cursors, stream)) + Box::pin(async move { + let response = client + .ingestion_state(&state_request) + .await + .map_err(|error| StreamSyncError::Refresh(error.to_string()))?; + Ok(cursor_for_stream(&response.cursors, stream)) + }) }, ) + .await .map_err(|source| TraceSyncError::Stream { stream: stream_label, source, })?; - let report = StreamSyncReport { + Ok(StreamSyncReport { uploaded: outcome.uploaded, initial_cursor: outcome.initial_cursor, final_cursor: outcome.final_cursor, batches: outcome.batches, - }; - progress.report(SyncProgressEvent::StreamCompleted { - stream: stream_label, - uploaded: report.uploaded, - cursor: report.final_cursor, - batches: report.batches, - }); - - Ok(report) + }) } /// A control-plane failure that cannot be resolved by reconciling with @@ -520,7 +632,7 @@ fn shared_runtime() -> Result<&'static Runtime, TraceSyncError> { mod tests { use std::fs; use std::path::PathBuf; - use std::time::{SystemTime, UNIX_EPOCH}; + use std::time::{Duration, SystemTime, UNIX_EPOCH}; use chrono::{DateTime, Utc}; use serde_json::json; @@ -531,7 +643,9 @@ mod tests { PartType, PAYLOAD_TYPE_PATCH, }; use crate::services::agent_trace_sync::control_plane::CredentialStore; - use crate::services::agent_trace_sync::test_http_server::{CannedResponse, TestHttpServer}; + use crate::services::agent_trace_sync::test_http_server::{ + CannedResponse, ConcurrentBatchTestServer, TestHttpServer, + }; use crate::services::auth::TokenResponse; use crate::services::token_storage::StoredTokens; @@ -579,14 +693,18 @@ mod tests { } fn test_client(server: &TestHttpServer) -> AuthenticatedControlPlaneClient { + test_client_at(&server.base_url) + } + + fn test_client_at(base_url: &str) -> AuthenticatedControlPlaneClient { let http = reqwest::Client::builder() .danger_accept_invalid_certs(true) .build() .expect("build test reqwest client"); AuthenticatedControlPlaneClient::with_credential_store( http, - server.base_url.clone(), - server.base_url.clone(), + base_url.to_string(), + base_url.to_string(), "test-client-id", Box::new(AlwaysValidCredentialStore), ) @@ -882,6 +1000,116 @@ mod tests { remove_test_db(&db_path); } + #[test] + fn concurrent_sync_overlaps_all_four_stream_batches_after_one_state_request() { + let db_path = unique_test_db_path("concurrent-overlap"); + let db = RepositoryAgentTraceDb::new_at(&db_path).expect("test DB should open"); + let metadata = db + .verify_or_initialize_repository_metadata("repo-concurrent-overlap") + .expect("metadata should initialize"); + seed_one_row_per_stream(&db); + + let server = ConcurrentBatchTestServer::start(Duration::from_millis(100)); + server.queue_state_response(CannedResponse::json(200, &state_response(0, 0, 0, 0))); + for stream in ["messages", "parts", "diff_traces", "agent_traces"] { + server.queue_batch_response(stream, 0, CannedResponse::json(200, &batch_response(1))); + } + let client = test_client_at(&server.base_url); + + let report = run_sync_against( + &metadata.repository_id, + &metadata.source_instance_id, + &db, + &client, + ) + .expect("concurrent sync should succeed"); + + assert_eq!(server.state_request_count(), 1); + assert_eq!(server.captured_requests().len(), 5); + assert_eq!(server.max_in_flight(), 4); + for stream in ["messages", "parts", "diff_traces", "agent_traces"] { + assert_eq!(server.max_in_flight_for(stream), 1, "stream {stream}"); + assert_eq!(server.expected_cursors_for(stream), vec![0]); + } + for stream in [ + report.streams.messages, + report.streams.parts, + report.streams.diff_traces, + report.streams.agent_traces, + ] { + assert_eq!(stream.uploaded, 1); + assert_eq!(stream.final_cursor, 1); + assert_eq!(stream.batches, 1); + } + + remove_test_db(&db_path); + } + + #[test] + fn concurrent_sync_keeps_batches_sequential_within_one_stream() { + let db_path = unique_test_db_path("concurrent-ordering"); + let db = RepositoryAgentTraceDb::new_at(&db_path).expect("test DB should open"); + let metadata = db + .verify_or_initialize_repository_metadata("repo-concurrent-ordering") + .expect("metadata should initialize"); + seed_messages(&db, 201); + + let server = ConcurrentBatchTestServer::start(Duration::from_millis(50)); + server.queue_state_response(CannedResponse::json(200, &state_response(0, 0, 0, 0))); + server.queue_batch_response( + "messages", + 0, + CannedResponse::json( + 200, + &json!({ + "accepted": 100, + "cursor": 100, + }), + ), + ); + server.queue_batch_response( + "messages", + 100, + CannedResponse::json( + 200, + &json!({ + "accepted": 100, + "cursor": 200, + }), + ), + ); + server.queue_batch_response( + "messages", + 200, + CannedResponse::json( + 200, + &json!({ + "accepted": 1, + "cursor": 201, + }), + ), + ); + let client = test_client_at(&server.base_url); + + let report = run_sync_against( + &metadata.repository_id, + &metadata.source_instance_id, + &db, + &client, + ) + .expect("ordered multi-batch sync should succeed"); + + assert_eq!(server.state_request_count(), 1); + assert_eq!(server.max_in_flight(), 1); + assert_eq!(server.max_in_flight_for("messages"), 1); + assert_eq!(server.expected_cursors_for("messages"), vec![0, 100, 200]); + assert_eq!(report.streams.messages.uploaded, 201); + assert_eq!(report.streams.messages.final_cursor, 201); + assert_eq!(report.streams.messages.batches, 3); + + remove_test_db(&db_path); + } + #[test] fn invalid_state_cursor_fails_before_any_batch_request() { let db_path = unique_test_db_path("invalid-cursor"); @@ -932,10 +1160,12 @@ mod tests { let server = TestHttpServer::start(); server.queue_response(CannedResponse::json(200, &state_response(0, 0, 0, 0))); - server.queue_response(CannedResponse::json( - 404, - &json!({"message": "unknown ingestion route"}), - )); + for _ in 0..4 { + server.queue_response(CannedResponse::json( + 404, + &json!({"message": "unknown ingestion route"}), + )); + } let client = test_client(&server); let error = run_sync_against( @@ -956,10 +1186,22 @@ mod tests { ), "unexpected error: {error:?}" ); + let requests = server.captured_requests(); assert_eq!( - server.call_count(), - 2, - "a terminal /batch status must fail immediately with no /state refetch and no resend" + requests + .iter() + .filter(|request| request.path == "/agent-trace/ingestion/state") + .count(), + 1, + "terminal /batch statuses must not trigger a /state refetch" + ); + let batch_count = requests + .iter() + .filter(|request| request.path == "/agent-trace/ingestion/batch") + .count(); + assert!( + (1..=4).contains(&batch_count), + "terminal /batch statuses must not resend batches; observed {batch_count}" ); remove_test_db(&db_path); @@ -976,10 +1218,12 @@ mod tests { let server = TestHttpServer::start(); server.queue_response(CannedResponse::json(200, &state_response(0, 0, 0, 0))); - server.queue_response(CannedResponse::json( - 404, - &json!({"message": "unknown ingestion route"}), - )); + for _ in 0..4 { + server.queue_response(CannedResponse::json( + 404, + &json!({"message": "unknown ingestion route"}), + )); + } let client = test_client(&server); let events = RefCell::new(Vec::new()); let clock = fixed_progress_clock(); @@ -1022,11 +1266,13 @@ mod tests { server.queue_response(CannedResponse::json(200, &state_response(0, 0, 0, 0))); // Syntactically successful but undecodable as `AgentTraceIngestionBatchResponse`. server.queue_response(CannedResponse::json(200, &json!({"unexpected": "shape"}))); - // Reconciliation refetch: cursor unchanged, so the batch is resent. - server.queue_response(CannedResponse::json(200, &state_response(0, 0, 0, 0))); + // The four initial stream requests overlap. Messages receives the + // malformed response, while the other streams receive their normal + // responses. Reconciliation then refetches state and resends messages. server.queue_response(CannedResponse::json(200, &batch_response(1))); server.queue_response(CannedResponse::json(200, &batch_response(1))); server.queue_response(CannedResponse::json(200, &batch_response(1))); + server.queue_response(CannedResponse::json(200, &state_response(0, 0, 0, 0))); server.queue_response(CannedResponse::json(200, &batch_response(1))); let client = test_client(&server); diff --git a/context/architecture.md b/context/architecture.md index d606e74b..39ca4116 100644 --- a/context/architecture.md +++ b/context/architecture.md @@ -132,7 +132,7 @@ The repository includes a new placeholder Rust binary crate at `cli/`. - `cli/src/services/hooks/mod.rs` defines the current local hook runtime parsing/dispatch (`HookSubcommand`, `run_hooks_subcommand`) plus a commit-msg co-author policy seam (`apply_commit_msg_coauthor_policy`) that injects one canonical SCE trailer only when the enabled-by-default attribution-hooks config/env control is not opted out, `SCE_DISABLED` is false, and the staged-diff AI-overlap preflight confirms AI/editor evidence (`StagedDiffAiOverlapResult::Overlap`); the preflight is wired into `run_commit_msg_subcommand_in_repo` and logs `sce.hooks.commit_msg.ai_overlap_error` on error paths; `cli/src/services/hooks/command.rs` owns the `HooksCommand` payload used by the static `RuntimeCommand` enum. In the current attribution-only baseline, `pre-commit` and `post-rewrite` are deterministic no-op surfaces; `post-commit` requires validated `--remote-url`, threads that URL through the Agent Trace flow, prints it to stderr, and remains an active intersection + Agent Trace persistence entrypoint (captures current commit patch, queries recent repository-level `diff_traces` from the bounded past-7-days window, combines valid patches via `patch::combine_patches`, intersects with post-commit patch via `patch::intersect_patches`, persists result to `post_commit_patch_intersections`, then persists built Agent Trace payloads with range-level `content_hash` values to `agent_traces` in the repository-scoped Agent Trace DB without post-commit file artifacts); `diff-trace` performs STDIN JSON intake, validates required non-empty `sessionID`/`diff`/`tool_name`, optional `model_id` (absent/`null` → `None`), required nullable/non-empty `tool_version` plus required `u64` `time` (Unix epoch milliseconds), rejects values that cannot fit signed `time_ms` storage, prefixes the stored `diff_traces.session_id` before insert construction (`oc_` for OpenCode, `cc_` for Claude, `pi_` for Pi, same-tool idempotent), and inserts the parsed payload fields into `RepositoryAgentTraceDb` without creating a parsed-payload `context/tmp` artifact; Claude structured `PostToolUse` diff-trace intake extracts direct model metadata from top-level or nested `model` fields and normalizes it with the `claude/` prefix when present. `session-model` is no longer a supported hook route. - Generated Claude settings no longer register `SessionStart` for Agent Trace model attribution, and `sce hooks session-model` is no longer a supported hook command. The `session_models` table/API and diff-trace fallback lookup were removed in T02 of the `remove-session-models-direct-claude-model-id` plan; `diff-trace` now uses only direct payload `model_id` and `tool_version` values. - `cli/src/services/resilience.rs` defines bounded retry/timeout/backoff execution policy (`RetryPolicy`, `run_with_retry`) for transient operation hardening with deterministic failure messaging and retry observability. -- `sce trace sync [--format text|json]` is implemented: `cli/src/services/trace/sync.rs` resolves repository-scoped Agent Trace storage the same way `sce trace status` does, authenticates against the control plane with stored WorkOS credentials, uses the config-resolved `control_plane_base_url` with baked default `https://sce.crocoderlab.dev`, calls the ingestion `/state` endpoint once, then synchronizes the `messages`/`parts`/`diff_traces`/`agent_traces` capture streams via `AgentTraceExportReader` and a shared per-stream reconciliation engine, and `cli/src/services/trace/render_sync.rs` renders the converged `AgentTraceSyncReport` as concise per-stream text or `camelCase` JSON (see `context/cli/trace-command.md`). Local DB bootstrap and setup-time repository-scoped Agent Trace DB initialization otherwise still flow through lifecycle providers aggregated by setup, while repository-scoped DB health/repair flows through the doctor surface. There is no checkout-scoped DB discovery or `sce trace --legacy` surface (removed by the `retire-legacy-agent-trace-db` plan). +- `sce trace sync [--format text|json]` is implemented: `cli/src/services/trace/sync.rs` resolves repository-scoped Agent Trace storage the same way `sce trace status` does, authenticates against the control plane with stored WorkOS credentials, uses the config-resolved `control_plane_base_url` with baked default `https://sce.crocoderlab.dev`, calls the ingestion `/state` endpoint once, then starts the `messages`/`parts`/`diff_traces`/`agent_traces` capture-stream state machines concurrently via `AgentTraceExportReader` and a shared per-stream reconciliation engine. Batches and cursor refreshes remain sequential within each stream, while fixed stream order is retained for final and stream-completion reporting; `cli/src/services/trace/render_sync.rs` renders the converged `AgentTraceSyncReport` as concise per-stream text or `camelCase` JSON (see `context/cli/trace-command.md`). Local DB bootstrap and setup-time repository-scoped Agent Trace DB initialization otherwise still flow through lifecycle providers aggregated by setup, while repository-scoped DB health/repair flows through the doctor surface. There is no checkout-scoped DB discovery or `sce trace --legacy` surface (removed by the `retire-legacy-agent-trace-db` plan). - `cli/src/services/patch.rs` defines the standalone patch domain model (`ParsedPatch`, `PatchFileChange`, `FileChangeKind`, `PatchHunk`, `TouchedLine`, `TouchedLineKind`) for in-memory parsed unified-diff representation, capturing only touched lines (added/removed) plus minimal per-file/per-hunk metadata while excluding non-hunk headers and unchanged context lines. All types are `serde`-serializable/deserializable with `snake_case` JSON field naming. The module also provides `parse_patch`, a public parser function that converts raw unified-diff text (both `Index:` SVN-style and `diff --git` git-style formats) into `ParsedPatch` structs, with `ParseError` for actionable malformed-input diagnostics. Storage-agnostic JSON load helpers (`load_patch_from_json` for string input, `load_patch_from_json_bytes` for byte input) reconstruct `ParsedPatch` from serialized JSON content with `PatchLoadError` for actionable deserialization diagnostics. Its patch-set operations now include deterministic ordered combination plus target-shaped intersection that prefers exact touched-line matches and falls back to historical `kind`+`content` matching when incremental diffs and canonical post-commit diffs have drifted line numbers; `parse_patch`, `combine_patches`, and `intersect_patches` are consumed by the active post-commit hook runtime. - `cli/src/services/structured_patch.rs` defines the synchronous structured editor-hook derivation seam. It derives Claude `PostToolUse` `Write` structured-update hunks, `Write` `tool_input.content` create fallback, and `Edit` structured-patch payloads into canonical `ParsedPatch` values plus Claude session/tool metadata, returning deterministic skip reasons for unsupported events/tools/payload shapes. The module is pure and side-effect-free. It is wired into `sce hooks diff-trace` for Claude payload classification at intake (T04) and into `RepositoryAgentTraceDb::recent_diff_trace_patches` for post-commit structured payload parsing dispatch at read time (T05). - `cli/src/services/` contains module boundaries for command_registry, lifecycle, auth_command, config, setup, doctor, hooks, checkout identity, bash_policy, version, completion, help, patch, SCE web URL helpers, shared database infrastructure, local DB adapters, encrypted auth DB adapters, and Agent Trace DB adapters with explicit trait seams for future implementations. `cli/src/services/checkout/` owns checkout ID file infrastructure (the per-checkout Agent Trace DB opener/path helper was removed by the `retire-legacy-agent-trace-db` plan); active setup/hooks use `agent_trace_storage` to establish checkout identity as diagnostics and initialize/open the repository-scoped DB, while `sce doctor` surfaces checkout identity facts plus credential-safe repository Agent Trace DB metadata. There is no checkout-scoped discovery or `sce trace --legacy` surface; any pre-migration `agent-trace-*.db` files on disk are never touched and no longer inspectable via the CLI. `cli/src/services/bash_policy.rs` owns both the CLI-agnostic evaluator logic and the hidden `sce policy bash` command adapter used by OpenCode, Claude, and Pi callers. `cli/src/services/command_registry.rs` defines the static `RuntimeCommand` enum, deterministic `CommandRegistry` name catalog, and `build_default_registry()` function for command dispatch metadata. Service-owned command modules own the runtime command payload structs for help/help-text, version, completion, auth, config, setup, doctor, hooks, and policy. diff --git a/context/cli/agent-trace-sync-command.md b/context/cli/agent-trace-sync-command.md index 236b3237..852e9745 100644 --- a/context/cli/agent-trace-sync-command.md +++ b/context/cli/agent-trace-sync-command.md @@ -24,11 +24,11 @@ flowchart LR - **hooks/plugins** write local capture rows (`messages`, `parts`, `diff_traces`, `agent_traces`) into the current repository's `RepositoryAgentTraceDb` during normal Git/editor activity — this is unchanged by sync. - **`AgentTraceExportReader`** (PR #198) is the read-only local export boundary sync uses to read rows after a cursor; sync never queries the repository DB directly. -- **`sce trace sync`** resolves repository storage through the same `agent_trace_storage` path `sce trace status` uses (not the hook-runtime resolver), builds an `AuthenticatedControlPlaneClient` from stored WorkOS credentials and the resolved `control_plane_base_url`, and drives one authoritative `/state` call plus one bounded per-stream reconciliation loop per stream. With no environment or config override, that base is `https://sce.crocoderlab.dev`; it is distinct from the `https://sce.crocoder.dev` SCE web and config-schema URL owner. -- **Credential runtime boundary:** `AuthenticatedControlPlaneClient` keeps the synchronous `CredentialStore` behind an `Arc` and runs every token-storage `load`/`save` through `tokio::task::spawn_blocking`. The underlying encrypted auth DB and Linux Secret Service/zbus APIs are blocking and may create their own Tokio runtime, so they must never execute directly inside the async control-plane request future. Token refresh and HTTP requests remain asynchronous; only credential persistence crosses the blocking boundary. +- **`sce trace sync`** resolves repository storage through the same `agent_trace_storage` path `sce trace status` uses (not the hook-runtime resolver), builds an `AuthenticatedControlPlaneClient` from stored WorkOS credentials and the resolved `control_plane_base_url`, and drives one authoritative `/state` call before starting four concurrent stream state machines. Each stream keeps its own batches and reconciliation refreshes sequential and cursor-safe; the bounded per-stream reconciliation loop remains independent. With no environment or config override, that base is `https://sce.crocoderlab.dev`; it is distinct from the `https://sce.crocoder.dev` SCE web and config-schema URL owner. +- **Credential runtime boundary:** `AuthenticatedControlPlaneClient` keeps the synchronous `CredentialStore` behind an `Arc` and runs every token-storage `load`/`save` through `tokio::task::spawn_blocking`. The underlying encrypted auth DB and Linux Secret Service/zbus APIs are blocking and may create their own Tokio runtime, so they must never execute directly inside the async control-plane request future. Token refresh and HTTP requests remain asynchronous; only credential persistence crosses the blocking boundary. The client owns a refresh single-flight guard: expired-token callers re-check credentials after acquiring it, and callers retrying the same rejected access token reuse a token saved by an earlier refresh; valid-token resolution does not acquire the guard. - **control plane** is the sole source of cursor truth: every invocation starts from `POST /agent-trace/ingestion/state`, uploads via `POST /agent-trace/ingestion/batch`, and advances a stream's cursor only from a validated batch response (`accepted == rows.len()` and `cursor == rows.last().sourceRowId`), never by inferring `cursor + rows.len()`. -The four streams (`messages`, `parts`, `diff_traces`, `agent_traces`) are independent and synchronized in that fixed order within one invocation. Text mode reports a UTC RFC3339 start timestamp before the first control-plane request, each validated accepted batch's size, cumulative uploaded rows, and current cursor, stream completion, and a terminal UTC RFC3339 end timestamp after success or failure through deterministic newline-delimited flushed lines on `stderr`; an empty stream reports that no new rows were uploaded. The timestamps come from an injectable clock for deterministic tests and do not alter the sync protocol or error classification. JSON mode uses a no-op progress sink and retains its JSON-only output contract without progress or lifecycle timestamps. +The four streams (`messages`, `parts`, `diff_traces`, `agent_traces`) start concurrently after the single authoritative state response; batches and cursor-refresh calls remain sequential within each stream. Fixed stream order applies to the final report and stream-completion reporting, while accepted-batch progress may arrive as requests complete. Text mode reports a UTC RFC3339 start timestamp before the first control-plane request, each validated accepted batch's size, cumulative uploaded rows, and current cursor, stream completion, and a terminal UTC RFC3339 end timestamp after success or failure through deterministic newline-delimited flushed lines on `stderr`; an empty stream reports that no new rows were uploaded. The timestamps come from an injectable clock for deterministic tests and do not alter the sync protocol or error classification. JSON mode uses a no-op progress sink and retains its JSON-only output contract without progress or lifecycle timestamps. ## No-local-persistence invariants @@ -43,7 +43,7 @@ Because every invocation starts from the control plane's authoritative `/state` ## Recovery semantics -- **`401` (unexpected):** the control-plane client refreshes the WorkOS token exactly once, saves it, and retries the request exactly once. A second `401` fails the command with `sce auth login` guidance; there is no further retry. +- **`401` (unexpected):** the control-plane client refreshes the WorkOS token exactly once, saves it, and retries the request exactly once. Concurrent callers that observed the same rejected token coalesce onto the first refresh and reuse its saved token; a second `401` fails the command with `sce auth login` guidance, and there is no further retry. - **`409` (cursor conflict):** the per-stream sync engine reconciles by refetching `/state`, replacing only the affected stream's cursor, and resuming from local rows after the refreshed cursor — already-accepted rows are never resent. - **Ambiguous batch failure (`5xx`, transport failure, or an undecodable `2xx` body):** the engine reconciles via `/state` before any resend. If the refreshed cursor advanced (the batch was actually committed), sync continues from it without resending. If the cursor is unchanged (the batch was not committed), sync may resend once from the authoritative cursor. - **Reconciliation bound:** both the `409` and ambiguous-failure reconciliation paths share one bounded attempt counter per stream; exhausting it fails that stream with a "did not converge" error instead of looping unboundedly. diff --git a/context/cli/trace-command.md b/context/cli/trace-command.md index c81b19b5..dfad706c 100644 --- a/context/cli/trace-command.md +++ b/context/cli/trace-command.md @@ -80,7 +80,7 @@ Text rendering shows discovery summary, totals, and a `By database` table with ` ### Sync — `services::trace::sync`, `render_sync` -`run_current_sync(repo_root)` resolves the current repository's Agent Trace storage through the same `agent_trace_storage` path `sce trace status` uses (not the hook-runtime resolver), builds an `AuthenticatedControlPlaneClient` from the resolved `control_plane_base_url`/`workos_client_id` config, and uses `https://sce.crocoderlab.dev` as the baked control-plane base when no override is configured. This control-plane host is separate from the SCE web/schema URL owned by `SCE_WEB_BASE_URL`. Sync calls the control-plane `/agent-trace/ingestion/state` endpoint once, then synchronizes the four independent capture streams (`messages`, `parts`, `diff_traces`, `agent_traces`, in that fixed order) via the local `AgentTraceExportReader` and the shared per-stream reconciliation engine, producing an `AgentTraceSyncReport`. A genuinely ambiguous batch outcome (`5xx`, transport failure, invalid response) reconciles by refetching `/state`; a terminal control-plane failure (missing/invalid credentials, `400`, `403`) fails the stream immediately without an extra network call, so a `403` never mutates local repository metadata or retries. No local sync cursor, cursor file, or database is created — every invocation starts from the authoritative `/state` cursors, so repeated runs are naturally incremental. +`run_current_sync(repo_root)` resolves the current repository's Agent Trace storage through the same `agent_trace_storage` path `sce trace status` uses (not the hook-runtime resolver), builds an `AuthenticatedControlPlaneClient` from the resolved `control_plane_base_url`/`workos_client_id` config, and uses `https://sce.crocoderlab.dev` as the baked control-plane base when no override is configured. This control-plane host is separate from the SCE web/schema URL owned by `SCE_WEB_BASE_URL`. Sync calls the control-plane `/agent-trace/ingestion/state` endpoint once, then starts four independent capture-stream state machines concurrently (`messages`, `parts`, `diff_traces`, `agent_traces`) via the local `AgentTraceExportReader` and the shared per-stream reconciliation engine. Batches and cursor-refresh calls remain sequential within each stream; fixed stream order applies to final reports and stream-completion reporting, not network execution. The authenticated client coalesces concurrent refreshes for the same expired or rejected access token while allowing valid-token requests to proceed without refresh coordination. A genuinely ambiguous batch outcome (`5xx`, transport failure, invalid response) reconciles by refetching `/state`; a terminal control-plane failure (missing/invalid credentials, `400`, `403`) fails the stream immediately without an extra network call, so a `403` never mutates local repository metadata or retries. No local sync cursor, cursor file, or database is created — every invocation starts from the authoritative `/state` cursors, so repeated runs are naturally incremental. `render_sync::render(report, format)` renders the converged `AgentTraceSyncReport`. In text mode, sync first emits deterministic live progress lines to `stderr`: a start line, one line for each accepted batch with the stream, batch size, cumulative uploaded rows, and server cursor, then one completion line per stream; an empty stream reports that no new rows were uploaded. These lines are newline-delimited and flushed as events arrive, so a slow upload is observable before the final report. The start line includes an injected-clock UTC RFC3339 timestamp and is emitted before the initial `/state` request; a terminal end line is emitted after successful completion or failure, preserving the classified error returned to the app. The final text output remains a `style::heading("Agent Trace sync complete.")` line, `Repository ID:`/`Source instance ID:` lines, then a padded table with one row per stream (`Stream`, `Uploaded`, `Final cursor`) in the fixed `messages → parts → diff_traces → agent_traces` order — no per-batch or per-row detail is added to the `stdout` payload. JSON mode uses a no-op progress sink and emits no human progress or lifecycle timestamps; its `stdout` output carries `status`, `command`, `subcommand`, `repositoryId`, `sourceInstanceId`, and `streams.{messages,parts,diffTraces,agentTraces}`, each with `uploaded`/`initialCursor`/`finalCursor`/`batches`; the JSON stream keys are camelCase (`diffTraces`/`agentTraces`) even though the internal `StreamSyncReports` struct fields are `diff_traces`/`agent_traces`. `TraceCommand::execute` dispatches `TraceSubcommandRequest::Sync { format }` through the format-specific progress sink and then to `render_sync::render`, completing the command surface end to end. diff --git a/context/glossary.md b/context/glossary.md index 38397a73..3007d47a 100644 --- a/context/glossary.md +++ b/context/glossary.md @@ -36,6 +36,7 @@ - `canonical OpenCode plugin registration source`: Shared Pkl-authored plugin-registration definition in `config/pkl/base/opencode.pkl`, re-exported from `config/pkl/renderers/common.pkl` as the canonical plugin list/path JSON consumed by OpenCode renderers before they emit generated `opencode.json` manifests; the current entries are `sce-bash-policy` and `sce-agent-trace`. - `checkout identity`: Stable UUIDv7 identifier assigned to a cloned repository or linked Git worktree, stored in `/sce/checkout-id` (never committed) and resolved via `git rev-parse --git-dir`. The identity is created or reused by `sce setup` through `AgentTraceDbLifecycle::setup()` and also auto-created by hook runtime when `sce setup` has not been run. Checkout identity is now diagnostic metadata for repository-scoped Agent Trace storage; it does not select the active DB and is not stored on Agent Trace rows. Any pre-migration per-checkout DB files at `/sce/agent-trace-{checkout_id}.db` are never touched by SCE and are no longer inspectable via the CLI (the checkout-scoped DB surface was removed by the `retire-legacy-agent-trace-db` plan). See `context/cli/checkout-identity.md`. - `repository identity`: Stable identity of a logical Git repository used to select the active repository-scoped Agent Trace DB path `/sce/repos//agent-trace.db` through the `agent_trace_storage` resolver. Resolved by `cli/src/services/repository_identity/` with precedence: explicit `agent_trace.repository_id` config value, then the URL of the configured Git remote (`agent_trace.repository_remote`, default `origin`), otherwise an actionable `.sce/config.json` error. Remote URLs canonicalize to a scheme-neutral, credential-free `host[:port]/path` form so equivalent SSH/SCP/HTTPS remotes converge, and the repository ID is `sha256("sce-repository-id-v1\0" + canonical_identity)` hex. Distinct from `checkout identity`, which stays per clone/worktree for diagnostics. See `context/cli/repository-identity.md`. +- `refresh single-flight guard`: Client-owned async coordination for Agent Trace control-plane authentication. Concurrent callers whose stored access token is expired, or whose request rejected the same token, serialize only refresh-and-save work, re-check credentials after acquiring the guard, and reuse the token saved by the first refresher; valid-token requests do not acquire the guard. - `repository-scoped Agent Trace DB`: Active Agent Trace storage shape where one logical Git repository maps to `/sce/repos//agent-trace.db`. The current seam is `RepositoryAgentTraceDb = TursoDb` in `cli/src/services/agent_trace_db/repository.rs`, backed by the fresh multi-statement `001_repository_schema` baseline plus the additive `002_repository_source_instance_id` migration, with `repository_metadata` (`repository_id` plus `source_instance_id`) plus repository-level trace tables, no `checkout_id` columns, and typed repository-level insert helpers for diff traces, post-commit intersections, Agent Trace rows, messages, and parts. Hook runtime, Agent Trace setup/lifecycle, and `sce trace` status/list/shell flows resolve repository-scoped storage through `agent_trace_storage`. This is the sole Agent Trace DB adapter; the checkout-scoped adapter and the `sce trace --legacy` inspection surface were removed by the `retire-legacy-agent-trace-db` plan. - `source_instance_id`: Physical-database identity column on `repository_metadata`, independent of the logical `repository_id`. Added by the additive `002_repository_source_instance_id` migration (existing/placeholder rows default to an empty string); generated once per physical `agent-trace.db` by application code (`generate_source_instance_id()`, UUID v4 today) and validated with `is_valid_source_instance_id()` (non-empty once trimmed) — never generated in SQL and never derived from `repository_id`, remote URL, checkout ID, filesystem path, hostname, or user/workspace identity. `RepositoryAgentTraceDb::verify_or_initialize_repository_metadata` claims it with a concurrency-safe `UPDATE ... WHERE source_instance_id = ''`, so concurrent first opens of the same physical database converge on one winner and an already-valid value is never overwritten; the value stays stable across reopen and repeated `sce setup` runs. Two independently created databases for the same logical repository (for example two clones) get different `source_instance_id` values. See `context/sce/agent-trace-db.md`. - `checkout registry` (removed): The central JSON registry at `/sce/checkout-registry.json` was removed in the `remove-checkout-registry` plan. `sce trace db list` now discovers checkouts by scanning `/sce/agent-trace-*.db` files on disk. `checkout_id`, `database_path`, and `last_seen` (from file mtime) are derived from the filesystem; `path` and `remote_url` are no longer rendered. See `context/cli/checkout-identity.md`. diff --git a/context/overview.md b/context/overview.md index 348196c5..dcc1be14 100644 --- a/context/overview.md +++ b/context/overview.md @@ -36,7 +36,7 @@ The same config resolver now also owns the attribution-hooks gate used by local The config service split now includes `cli/src/services/config/resolver.rs` as the focused owner for config-file discovery, file-layer merging, env/flag/default precedence, auth-key resolution, observability resolution, attribution-hooks resolution, and default-discovered invalid-file degradation; `cli/src/services/config/mod.rs` remains the facade/rendering orchestration surface while preserving existing `services::config` imports. Generated config now includes repo-local OpenCode plugin assets: `sce-bash-policy.ts` plus `sce-agent-trace.ts` are emitted under `config/.opencode/plugins/`; the OpenCode agent-trace plugin extracts `{ sessionID, diff, time, model_id }` from user `message.updated` events with diffs, tracks per-session OpenCode client version from `session.created`/`session.updated`, and sends payloads to `sce hooks diff-trace` with `tool_name="opencode"` plus optional `tool_version`. Claude generated config now routes supported `PostToolUse Write|Edit|MultiEdit|NotebookEdit` events directly to `sce hooks diff-trace`; it no longer registers a `SessionStart` hook or calls `sce hooks session-model`. Rust handles extraction, validation, and persistence without a TypeScript intermediary; the former `config/.claude/plugins/sce-agent-trace.ts` Bun runtime was removed in T07 of the `claude-rust-diff-trace` plan. The Rust hook validates required fields, uses only direct payload `model_id` and `tool_version` (no longer resolves from `session_models`), and persists tool-prefixed `session_id` values (`oc_` for OpenCode, `cc_` for Claude, `pi_` for Pi), `model_id`, `tool_name`, and nullable `tool_version` into `diff_traces` through AgentTraceDb. Bash-policy now delegates OpenCode enforcement to the Rust `sce policy bash` command: the generated OpenCode plugin at `config/.opencode/plugins/sce-bash-policy.ts` is a thin wrapper that calls `sce policy bash --input normalized --output json` via `spawnSync` and throws on deny decisions; it no longer contains independent TypeScript policy logic. The former `bash-policy/runtime.ts` TypeScript runtime has been removed. Preset... Claude bash-policy enforcement is also generated through `.claude/settings.json` as a `PreToolUse` `Bash` command hook running `sce policy bash`, so Claude and OpenCode both delegate to the Rust policy evaluator without a Claude TypeScript runtime. Pi bash-policy enforcement is delegated the same way through a project-local Pi extension (`config/lib/pi-plugin/sce-pi-extension.ts`, emitted to `config/.pi/extensions/sce/index.ts`) whose `tool_call` handler blocks denied bash commands via `sce policy bash` and fails open when the policy check cannot run (see `context/sce/pi-extension-runtime.md`). -Local database bootstrap is now owned by `LocalDbLifecycle::setup` and `AgentTraceDbLifecycle::setup` aggregated by the setup command. Agent Trace setup creates/reuses the current checkout ID for diagnostics and initializes the repository-scoped `/sce/repos//agent-trace.db` with the repository schema; hook runtime lazily creates or upgrades that repository DB when setup has not run or schema metadata is incomplete. Doctor validates the repository-scoped DB path/health and can bootstrap missing parent directories; outside a Git repository it reports an actionable "requires a Git repository" diagnostic instead of probing a sentinel path. The `sce trace` group operates only on repository-scoped DBs for list/status/status-all/shell UX; the checkout-scoped `--legacy` surface was removed by the `retire-legacy-agent-trace-db` plan (see `context/decisions/2026-07-17-retire-legacy-agent-trace-db.md`). `sce trace sync` is now fully implemented: it resolves repository-scoped storage, authenticates against the control plane with stored WorkOS credentials, synchronizes the four Agent Trace capture streams, and renders the documented concise text/JSON output (see `context/cli/trace-command.md`). +Local database bootstrap is now owned by `LocalDbLifecycle::setup` and `AgentTraceDbLifecycle::setup` aggregated by the setup command. Agent Trace setup creates/reuses the current checkout ID for diagnostics and initializes the repository-scoped `/sce/repos//agent-trace.db` with the repository schema; hook runtime lazily creates or upgrades that repository DB when setup has not run or schema metadata is incomplete. Doctor validates the repository-scoped DB path/health and can bootstrap missing parent directories; outside a Git repository it reports an actionable "requires a Git repository" diagnostic instead of probing a sentinel path. The `sce trace` group operates only on repository-scoped DBs for list/status/status-all/shell UX; the checkout-scoped `--legacy` surface was removed by the `retire-legacy-agent-trace-db` plan (see `context/decisions/2026-07-17-retire-legacy-agent-trace-db.md`). `sce trace sync` is now fully implemented: it resolves repository-scoped storage, authenticates against the control plane with stored WorkOS credentials, fetches authoritative cursors once, synchronizes the four Agent Trace capture streams concurrently while preserving sequential batches within each stream, and renders the documented concise text/JSON output (see `context/cli/trace-command.md`). The repository-root flake (`flake.nix`) applies a Rust overlay-backed stable toolchain pinned to `1.95.0` (with `rustfmt` and `clippy`), reads package/check version from the repo-root `.version` file, and builds `packages.sce` through a Crane `buildDepsOnly` + `buildPackage` pipeline. One deterministic pre-Cargo Nix derivation invokes the shared generated-input producer and supplies its validated `SCE_CLI_GENERATED_INPUT_DIR` store path to native, release, test, and Clippy Cargo derivations. Pkl is absent from those Cargo environments; dependency-only and format derivations do not receive the handoff, so canonical generation changes invalidate compiling outputs without invalidating dependency artifacts or formatting. `cli-tests`, `cli-clippy`, and `cli-fmt` remain Crane-backed check derivations. The root flake splits native and release outputs: `packages.sce` and `packages.default` build the **native** development binary (`scePackage`), while `packages.sce-release` builds the release binary (`sceReleasePackage`: static musl on Linux, native on Darwin). So `nix build .#sce` / `.#default`, `nix run . -- --help`, `nix run .#sce -- --help`, and `nix profile install github:crocoder-dev/shared-context-engineering` target the native binary, and `nix build .#sce-release` / `nix run .#sce-release -- ...` (plus `nix run .#release-artifacts`, which builds `.#sce-release`) target the release binary. On Linux the native and release outputs are distinct store paths, and the release output passes the native portability audit. `packages..ci-checks` is the explicit long-running validation tier: `nix build .#ci-checks` builds the `.#sce-release` package and, on Linux, audits the real release binary for forbidden `/nix/store/` references, so the expensive work stays out of `nix flake check` (which never builds `.#sce-release`). Git-commit embedding is **release-only**: `SCE_GIT_COMMIT` is injected via a `releaseCommitArgs` fragment applied only to the release derivations (`scePackageMusl` on Linux, `sceReleasePackageNative` on Darwin), not to `commonCargoArgs`. So native `.#sce`/`.#default` and every `nix flake check` derivation (`cli-tests`, `cli-clippy`, `cli-fmt`) build without the commit in their inputs and stay cache-reusable across commits (native `sce version` reports `unknown`), while `.#sce-release` still reports the real commit via `sce version`. `cli/build.rs` `emit_git_commit` emits `SCE_GIT_COMMIT` only when the env var is explicitly set — no `git rev-parse` fallback and no `.git/HEAD`/`.git/packed-refs` rerun watches. On Darwin the release now uses a distinct native-toolchain derivation (native toolchain + commit), so it diverges from `.#sce` to carry the commit while native stays commit-independent. diff --git a/context/plans/agent-trace-sync-concurrency.md b/context/plans/agent-trace-sync-concurrency.md new file mode 100644 index 00000000..6743eec0 --- /dev/null +++ b/context/plans/agent-trace-sync-concurrency.md @@ -0,0 +1,114 @@ +# Plan: agent-trace-sync-concurrency + +## Change summary + +Refactor `sce trace sync` so its four independent Agent Trace ingestion streams (`messages`, `parts`, `diff_traces`, and `agent_traces`) execute as concurrent async state machines after one authoritative `/agent-trace/ingestion/state` request. The current synchronous `sync_stream` callbacks and nested `runtime.block_on(...)` calls serialize the HTTP requests; the change will move stream ingest and cursor-refresh callbacks to awaitable futures, keep cursor-dependent batches sequential within each stream, and use one outer runtime boundary around the overall sync operation. + +Preserve the existing cursor validation, batching, `409` and ambiguous-failure reconciliation, terminal-error classification, progress/reporting, output, and no-local-sync-state behavior. Add refresh single-flight coordination so simultaneous expired-token requests share one refresh while ordinary valid-token requests remain concurrent. Extend the test HTTP helper with a concurrent, delayed-batch mode that records global and per-stream in-flight maxima, then add regressions proving four-way overlap and single-stream ordering. + +## Acceptance criteria + +- [x] AC1: One initial `/agent-trace/ingestion/state` response supplies all four starting cursors, and with one pending batch in each stream the test control plane observes `max_in_flight == 4` concurrent `/batch` requests. + - Validate: `trace::sync` concurrency regression test using the concurrent delayed test server; assert exactly one state request and four overlapping batch requests. +- [x] AC2: Batches within an individual stream remain sequential and cursor-safe: a stream never has two batch requests in flight, and batch N+1 uses the cursor returned by batch N. + - Validate: the delayed server's per-stream in-flight maximum and captured expected-cursor assertions; existing `agent_trace_sync::tests` cursor, batching, and reconciliation tests. +- [x] AC3: Existing reconciliation and terminal behavior remains unchanged for `409`, ambiguous transport/5xx/invalid-2xx outcomes, `/state` refreshes, terminal errors, invalid cursors, and reporting/output. + - Validate: the existing `agent_trace_sync::` and `trace::sync::` test suites, including full/incremental, conflict, malformed-response, terminal-error, auth, cursor-validation, and progress tests, through the CLI flake test check. +- [x] AC4: Concurrent requests with an expired stored token cause at most one refresh operation for the shared client; all callers use the resulting token, while valid-token requests do not serialize behind refresh coordination unnecessarily. + - Validate: control-plane concurrency tests with a delayed refresh response and a counting credential store assert one refresh/save and successful requests from all four callers; valid-token reuse tests continue to assert zero refresh/save calls. +- [x] AC5: No nested `runtime.block_on(...)` remains in per-stream ingest or reconciliation callbacks; the synchronous CLI boundary performs at most one `block_on` around the complete async sync operation. + - Validate: source inspection of `cli/src/services/trace/sync.rs` plus the async orchestration tests. +- [x] AC6: Human text progress and final text/JSON output remain deterministic and contract-compatible despite concurrent stream completion. + - Validate: existing progress/rendering tests and the full CLI test check; final stream rendering remains in the documented fixed stream order. + +### Full validation + +- `nix run .#pkl-check-generated` +- `nix flake check` + +### Context sync + +- `context/cli/agent-trace-sync-command.md` — document concurrent stream execution, per-stream sequential ordering, and refresh single-flight behavior. +- `context/cli/trace-command.md` — update the sync behavior description so fixed ordering applies to reporting/contract order, not serial execution. +- `context/overview.md` and `context/architecture.md` — update the current Agent Trace sync data-flow/architecture claims where they describe the four streams as fixed-order execution. + +## Constraints and non-goals + +- **In scope:** async conversion of `cli/src/services/agent_trace_sync/mod.rs` and `cli/src/services/trace/sync.rs`; refresh coordination in `cli/src/services/agent_trace_sync/control_plane.rs`; concurrent test-server support and regression tests in the existing Agent Trace sync test modules; the listed current-state context updates. +- **Out of scope:** wire-protocol changes, local database schema or persistence changes, local sync cursors, control-plane server changes, unrelated CLI command or rendering redesign, and background/daemon synchronization. +- **Constraints:** fetch `/state` once before starting streams; preserve one in-flight batch per stream and server-cursor ordering within each stream; use the existing single-thread Tokio runtime without introducing OS threads for production concurrency; preserve public synchronous CLI behavior, authentication semantics, error classification, progress routing, and output shapes; keep dependencies unchanged unless the existing Tokio/reqwest APIs cannot provide the required seam. +- **Non-goal:** making batches from one stream concurrent, replacing authoritative `/state` reconciliation with local state, or redesigning authentication/token storage beyond a narrowly scoped refresh single-flight mechanism. + +## Assumptions + +- `tokio::join!` or an equivalent structured-concurrency combinator will run the four stream futures on the existing current-thread runtime; reqwest's asynchronous socket waits provide HTTP overlap without application-created OS threads. +- The outer progress-sink API remains synchronous. Internal stream progress delivery may use a small shared event-emission seam or equivalent coordination, but events must still be reported as batches complete and final reports must retain the documented stream order. +- Refresh single-flight coordination will guard only refresh-and-save operations and will re-check stored credentials after acquiring the guard, so normal requests holding a valid token can proceed concurrently and callers do not repeat a refresh another caller just completed. +- The existing sequential `TestHttpServer::start()` behavior may remain for order-sensitive legacy tests; a concurrent server mode or replacement helper will be used for overlap tests, with route-aware/dynamic batch responses where queued response order would otherwise be nondeterministic. + +## Task stack + +- [x] T01: `Refactor stream synchronization to async concurrent orchestration` (status:done) + - Task ID: T01 + - Goal: Make `sync_stream` an async state machine with awaitable read, ingest, and cursor-refresh callbacks, make `sync_one_stream` async without nested runtime bridging, and run all four stream futures concurrently after the single initial `/state` call while preserving per-stream batch sequencing and existing reconciliation/reporting semantics. + - Boundaries (in/out of scope): In — `cli/src/services/agent_trace_sync/mod.rs`, `cli/src/services/trace/sync.rs`, the outer synchronous runtime boundary, async-compatible progress/event coordination, and updates required to compile and preserve the existing engine/orchestration tests. Out — token refresh coordination, concurrent HTTP test-server implementation, wire changes, and database/persistence changes. + - Dependencies: none + - Done when: the initial state is awaited once; four stream futures are joined; each stream awaits its own next read/ingest/refresh before advancing; all existing reconciliation, cursor-validation, progress, and incremental-sync tests pass; no per-stream callback calls `runtime.block_on(...)`. + - Implementation evidence: `sync_stream` is now an awaitable state machine; `run_sync_async` fetches `/state` once, joins four stream futures with per-stream sequential awaits, and emits completion reports in fixed stream order. `cli/src/services/trace/sync.rs` has one production `runtime.block_on(...)` around the complete async operation; batch ingestion and reconciliation callbacks are awaitable. + - Verification notes (commands or checks): `nix build .#checks.x86_64-linux.cli-tests` passed; focused `agent_trace_sync` and `trace::sync::tests` suites passed via `nix develop -c ./scripts/run-cli-cargo.sh test --manifest-path cli/Cargo.toml ...`; `git diff --check` passed; source inspection confirmed the single production runtime bridge. + +- [x] T02: `Coalesce concurrent access-token refreshes` (status:done) + - Task ID: T02 + - Goal: Add a small client-owned single-flight refresh guard and double-check logic so concurrent expired-token resolution, and concurrent forced refreshes when applicable, do not issue duplicate WorkOS refresh/save operations while preserving valid-token request concurrency and the existing one-refresh/one-retry `401` contract. + - Boundaries (in/out of scope): In — `AuthenticatedControlPlaneClient` refresh coordination, credential re-checking, and focused control-plane tests with delayed/counting fake credentials and refresh responses. Out — changing token formats, credential storage, WorkOS endpoints, ordinary request scheduling, or sync-stream logic. + - Dependencies: T01 + - Done when: four concurrent client operations sharing an expired credential perform one refresh and one save, all complete with the refreshed access token, valid credentials still produce zero refresh/save calls, and existing 401 success/failure behavior remains unchanged. + - Implementation evidence: `AuthenticatedControlPlaneClient` now owns a Tokio refresh mutex; expired-token resolution re-loads credentials after acquiring it, and unexpected-`401` refreshes reuse a token saved for the rejected access token instead of refreshing again. Focused concurrency coverage uses four coordinated expired-token callers and asserts one WorkOS refresh, one credential save, and four successful requests with the refreshed token. + - Verification notes (commands or checks): `nix develop -c ./scripts/run-cli-cargo.sh test --manifest-path cli/Cargo.toml services::agent_trace_sync::control_plane::tests` passed (28 tests); `nix build .#checks.x86_64-linux.cli-tests` passed; `nix develop -c ./scripts/run-cli-cargo.sh test --manifest-path cli/Cargo.toml services::trace::sync::tests -- --test-threads=1` passed (7 tests); `git diff --check` passed. + +- [x] T03: `Add concurrent overlap and ordering regression coverage` (status:done) + - Task ID: T03 + - Goal: Extend or replace the test HTTP helper with a concurrent connection mode that delays batch responses and tracks global/per-stream in-flight counts, then add end-to-end regressions for four-stream overlap and same-stream sequential batches while retaining the existing order-sensitive tests and update the affected durable sync documentation. + - Boundaries (in/out of scope): In — `cli/src/services/agent_trace_sync/test_http_server.rs`, `cli/src/services/trace/sync.rs` tests and any focused control-plane tests needed for the helper, plus the listed context files; dynamic batch response validation based on request stream/cursor and deterministic overlap assertions. Out — production server behavior, new test dependencies, changes to wire payloads, and unrelated context cleanup. + - Dependencies: T01, T02 + - Done when: a seeded one-row-per-stream test asserts one `/state` request and `max_in_flight == 4`; a multi-batch stream test asserts that stream's in-flight maximum is one and expected cursors advance batch-by-batch; the full existing sync/auth/reconciliation/progress/output suite remains green; current-state context describes concurrency accurately. + - Implementation evidence: Added `ConcurrentBatchTestServer` with delayed, per-stream/cursor-routed responses, global and per-stream in-flight maxima, and captured expected cursors. Added end-to-end regressions proving one authoritative `/state` request, four-way batch overlap, and sequential same-stream cursor advancement. Preserved the sequential helper for existing order-sensitive tests and made terminal-failure request-count assertions tolerant of early structured-concurrency cancellation while still proving no refresh or resend. + - Verification notes (commands or checks): `nix build .#checks.x86_64-linux.cli-tests` passed; `nix run .#pkl-check-generated` passed; `nix flake check` passed; focused `services::trace::sync::tests` (9 tests) and `services::agent_trace_sync` (37 tests) passed; `git diff --check` passed. + +## Open questions + +None. The request identifies the broken serialization mechanism, the required concurrency boundaries, authentication race behavior, test observables, and explicit non-goals. The current code confirms the premise: `sync_stream` and its callbacks are synchronous, `trace/sync.rs` calls `runtime.block_on(...)` per stream operation, and the existing test server handles connections serially; no clarification would materially change the scope or acceptance criteria. + +## Validation Report + +**Status:** validated +**Date:** 2026-08-13 + +### Commands run + +- `nix run .#pkl-check-generated` -> exit 0 (ephemeral generated-output parity passed) +- `nix flake check` -> exit 0 (all flake checks passed) +- `nix build .#checks.x86_64-linux.cli-tests` -> exit 0 (CLI test check passed) +- `nix develop -c sh -c 'set -e; ./scripts/run-cli-cargo.sh test --manifest-path cli/Cargo.toml services::trace::sync::tests -- --test-threads=1; ./scripts/run-cli-cargo.sh test --manifest-path cli/Cargo.toml services::agent_trace_sync -- --test-threads=1'` -> exit 0 (9 trace sync and 37 Agent Trace sync tests passed) +- `nix shell nixpkgs#ripgrep -c rg -n "runtime\\.block_on|block_on" cli/src/services/trace/sync.rs cli/src/services/agent_trace_sync/mod.rs; nix shell nixpkgs#ripgrep -c rg -n "run_sync_async|join!|join_all" cli/src/services/trace/sync.rs` -> exit 0 (one production runtime bridge; async joined orchestration confirmed) + +### Scaffolding removed + +- None. + +### Success-criteria verification + +- [x] AC1: One initial `/agent-trace/ingestion/state` response supplies all four starting cursors, and with one pending batch in each stream the test control plane observes `max_in_flight == 4` concurrent `/batch` requests. -> `concurrent_sync_overlaps_all_four_stream_batches_after_one_state_request` passed; observed one state request and four-way overlap. +- [x] AC2: Batches within an individual stream remain sequential and cursor-safe: a stream never has two batch requests in flight, and batch N+1 uses the cursor returned by batch N. -> `concurrent_sync_keeps_batches_sequential_within_one_stream` passed; per-stream maximum was one and captured cursors advanced correctly. Existing cursor, batching, and reconciliation tests also passed. +- [x] AC3: Existing reconciliation and terminal behavior remains unchanged for `409`, ambiguous transport/5xx/invalid-2xx outcomes, `/state` refreshes, terminal errors, invalid cursors, and reporting/output. -> 37 Agent Trace sync and 9 trace sync tests passed, including reconciliation, classification, cursor, terminal, and output/progress coverage. +- [x] AC4: Concurrent requests with an expired stored token cause at most one refresh operation for the shared client; all callers use the resulting token, while valid-token requests do not serialize behind refresh coordination unnecessarily. -> `concurrent_expired_tokens_share_one_refresh_and_save` and valid-token reuse tests passed in the 37-test Agent Trace sync suite. +- [x] AC5: No nested `runtime.block_on(...)` remains in per-stream ingest or reconciliation callbacks; the synchronous CLI boundary performs at most one `block_on` around the complete async sync operation. -> Source inspection found one production `runtime.block_on` in `trace/sync.rs`; orchestration and async stream tests passed. +- [x] AC6: Human text progress and final text/JSON output remain deterministic and contract-compatible despite concurrent stream completion. -> Progress/final-report tests passed in the trace sync suite; fixed stream-order reporting is retained by `run_sync_async`. + +### Failed checks and follow-ups + +- None. + +### Residual risks + +- None identified.