mirror of
https://github.com/openai/codex.git
synced 2026-11-10 21:00:47 +00:00
Keep thread storage available when diagnostic logs fail (#60466)
## Why Failure to open the diagnostic logs database should not disable thread storage or database-only history listing. Thread deletion must still preserve saved conversations when diagnostic log cleanup cannot complete. ## What changed - Allow state initialization to continue after non-corruption errors opening the logs database, while preserving corruption recovery. - Report the original diagnostic database error after tracing is installed in the TUI and app server, and return it from log operations. - Reject thread deletion before destructive cleanup when diagnostic storage failed to initialize. - Continue periodic cleanup of legacy logs when the current logs database is unavailable. ## Testing Extend coverage for unavailable log directories, database-only history listing, startup diagnostics, deletion preserving saved conversations, corrupt log headers, and periodic legacy log cleanup during a diagnostic storage outage. GitOrigin-RevId: a5184580ae6c39ed0c4eefa8cb48ee7731a991c3
This commit is contained in:
committed by
copyberry
parent
e1cc96712f
commit
caae161dd0
@@ -102,7 +102,8 @@ pub struct StateRuntime {
|
||||
sqlite: SqliteConfig,
|
||||
default_provider: String,
|
||||
pool: Arc<sqlx::SqlitePool>,
|
||||
logs_pool: Arc<sqlx::SqlitePool>,
|
||||
logs_pool: Option<Arc<sqlx::SqlitePool>>,
|
||||
diagnostic_logs_error: Option<String>,
|
||||
thread_goals: GoalStore,
|
||||
memories: MemoryStore,
|
||||
memories_v2: Arc<tokio::sync::OnceCell<MemoryStore>>,
|
||||
@@ -159,16 +160,22 @@ impl StateRuntime {
|
||||
}
|
||||
};
|
||||
let has_memories_v2 = tokio::fs::try_exists(sqlite.memories_v2_db_path()).await?;
|
||||
let logs_pool = match sqlite
|
||||
let (logs_pool, diagnostic_logs_error) = match sqlite
|
||||
.open_logs_db(&logs_migrator, telemetry_override)
|
||||
.await
|
||||
{
|
||||
Ok(db) => Arc::new(db),
|
||||
Err(err) => {
|
||||
warn!("failed to open logs db at {}: {err}", logs_path.display());
|
||||
close_sqlite_pools(&[pool.as_ref()]).await;
|
||||
Ok(db) => (Some(Arc::new(db)), None),
|
||||
Err(err) if is_sqlite_corruption_error(&err) => {
|
||||
pool.close().await;
|
||||
return Err(err);
|
||||
}
|
||||
Err(err) => (
|
||||
None,
|
||||
Some(format!(
|
||||
"failed to open logs db at {}: {err:#}",
|
||||
logs_path.display()
|
||||
)),
|
||||
),
|
||||
};
|
||||
let goals_pool = match sqlite
|
||||
.open_goals_db(&goals_migrator, telemetry_override)
|
||||
@@ -177,7 +184,7 @@ impl StateRuntime {
|
||||
Ok(db) => Arc::new(db),
|
||||
Err(err) => {
|
||||
warn!("failed to open goals db at {}: {err}", goals_path.display());
|
||||
close_sqlite_pools(&[pool.as_ref(), logs_pool.as_ref()]).await;
|
||||
close_sqlite_pools(&[Some(pool.as_ref()), logs_pool.as_deref()]).await;
|
||||
return Err(err);
|
||||
}
|
||||
};
|
||||
@@ -191,7 +198,12 @@ impl StateRuntime {
|
||||
"failed to open memories db at {}: {err}",
|
||||
memories_path.display()
|
||||
);
|
||||
close_sqlite_pools(&[pool.as_ref(), logs_pool.as_ref(), goals_pool.as_ref()]).await;
|
||||
close_sqlite_pools(&[
|
||||
Some(pool.as_ref()),
|
||||
logs_pool.as_deref(),
|
||||
Some(goals_pool.as_ref()),
|
||||
])
|
||||
.await;
|
||||
return Err(err);
|
||||
}
|
||||
};
|
||||
@@ -203,10 +215,10 @@ impl StateRuntime {
|
||||
Err(err) => {
|
||||
warn!("failed to open queue db at {}: {err}", queue_path.display());
|
||||
close_sqlite_pools(&[
|
||||
pool.as_ref(),
|
||||
logs_pool.as_ref(),
|
||||
goals_pool.as_ref(),
|
||||
memories_pool.as_ref(),
|
||||
Some(pool.as_ref()),
|
||||
logs_pool.as_deref(),
|
||||
Some(goals_pool.as_ref()),
|
||||
Some(memories_pool.as_ref()),
|
||||
])
|
||||
.await;
|
||||
return Err(err);
|
||||
@@ -223,11 +235,11 @@ impl StateRuntime {
|
||||
);
|
||||
if let Err(err) = backfill_state_result {
|
||||
close_sqlite_pools(&[
|
||||
pool.as_ref(),
|
||||
logs_pool.as_ref(),
|
||||
goals_pool.as_ref(),
|
||||
memories_pool.as_ref(),
|
||||
queue_pool.as_ref(),
|
||||
Some(pool.as_ref()),
|
||||
logs_pool.as_deref(),
|
||||
Some(goals_pool.as_ref()),
|
||||
Some(memories_pool.as_ref()),
|
||||
Some(queue_pool.as_ref()),
|
||||
])
|
||||
.await;
|
||||
return Err(err);
|
||||
@@ -252,11 +264,11 @@ impl StateRuntime {
|
||||
Ok(value) => value,
|
||||
Err(err) => {
|
||||
close_sqlite_pools(&[
|
||||
pool.as_ref(),
|
||||
logs_pool.as_ref(),
|
||||
goals_pool.as_ref(),
|
||||
memories_pool.as_ref(),
|
||||
queue_pool.as_ref(),
|
||||
Some(pool.as_ref()),
|
||||
logs_pool.as_deref(),
|
||||
Some(goals_pool.as_ref()),
|
||||
Some(memories_pool.as_ref()),
|
||||
Some(queue_pool.as_ref()),
|
||||
])
|
||||
.await;
|
||||
return Err(err);
|
||||
@@ -272,6 +284,7 @@ impl StateRuntime {
|
||||
thread_queue: SqliteQueueStore::new(queue_pool),
|
||||
pool,
|
||||
logs_pool,
|
||||
diagnostic_logs_error,
|
||||
sqlite,
|
||||
default_provider,
|
||||
thread_updated_at_millis: Arc::new(AtomicI64::new(thread_updated_at_millis)),
|
||||
@@ -309,6 +322,21 @@ impl StateRuntime {
|
||||
&self.thread_queue
|
||||
}
|
||||
|
||||
/// Startup failure to report after tracing is installed and before destructive cleanup.
|
||||
pub fn diagnostic_logs_error(&self) -> Option<&str> {
|
||||
self.diagnostic_logs_error.as_deref()
|
||||
}
|
||||
|
||||
fn diagnostic_logs_pool(&self) -> anyhow::Result<&SqlitePool> {
|
||||
self.logs_pool.as_deref().ok_or_else(|| {
|
||||
anyhow::anyhow!(
|
||||
"diagnostic database unavailable: {}",
|
||||
self.diagnostic_logs_error()
|
||||
.unwrap_or("logs pool was not initialized")
|
||||
)
|
||||
})
|
||||
}
|
||||
|
||||
/// Close all SQLite pools and wait for outstanding pool workers to exit.
|
||||
pub async fn close(&self) {
|
||||
self.reclamation.close().await;
|
||||
@@ -318,7 +346,9 @@ impl StateRuntime {
|
||||
memories.close().await;
|
||||
}
|
||||
self.thread_goals.close().await;
|
||||
self.logs_pool.close().await;
|
||||
if let Some(pool) = &self.logs_pool {
|
||||
pool.close().await;
|
||||
}
|
||||
self.pool.close().await;
|
||||
}
|
||||
|
||||
@@ -355,8 +385,8 @@ impl StateRuntime {
|
||||
}
|
||||
}
|
||||
|
||||
async fn close_sqlite_pools(pools: &[&SqlitePool]) {
|
||||
for pool in pools {
|
||||
async fn close_sqlite_pools(pools: &[Option<&SqlitePool>]) {
|
||||
for pool in pools.iter().flatten() {
|
||||
pool.close().await;
|
||||
}
|
||||
}
|
||||
|
||||
@@ -11,7 +11,7 @@ impl StateRuntime {
|
||||
return Ok(());
|
||||
}
|
||||
|
||||
let mut tx = self.logs_pool.begin().await?;
|
||||
let mut tx = self.diagnostic_logs_pool()?.begin().await?;
|
||||
let mut builder = QueryBuilder::<Sqlite>::new(
|
||||
"INSERT INTO logs (ts, ts_nanos, level, target, feedback_log_body, thread_id, process_uuid, module_path, file, line, estimated_bytes) ",
|
||||
);
|
||||
@@ -300,7 +300,7 @@ WHERE id IN (
|
||||
|
||||
let rows = builder
|
||||
.build_query_as::<LogRow>()
|
||||
.fetch_all(self.logs_pool.as_ref())
|
||||
.fetch_all(self.diagnostic_logs_pool()?)
|
||||
.await?;
|
||||
Ok(rows)
|
||||
}
|
||||
@@ -310,7 +310,7 @@ WHERE id IN (
|
||||
&self,
|
||||
thread_ids: &[&str],
|
||||
) -> anyhow::Result<Vec<u8>> {
|
||||
Self::query_feedback_logs_from_pool(self.logs_pool.as_ref(), thread_ids).await
|
||||
Self::query_feedback_logs_from_pool(self.diagnostic_logs_pool()?, thread_ids).await
|
||||
}
|
||||
|
||||
/// Read logs from the previous directory without creating or migrating its database.
|
||||
@@ -441,7 +441,10 @@ WHERE cumulative_estimated_bytes <=
|
||||
let mut builder =
|
||||
QueryBuilder::<Sqlite>::new("SELECT MAX(id) AS max_id FROM logs WHERE 1 = 1");
|
||||
push_log_filters(&mut builder, query);
|
||||
let row = builder.build().fetch_one(self.logs_pool.as_ref()).await?;
|
||||
let row = builder
|
||||
.build()
|
||||
.fetch_one(self.diagnostic_logs_pool()?)
|
||||
.await?;
|
||||
let max_id: Option<i64> = row.try_get("max_id")?;
|
||||
Ok(max_id.unwrap_or(0))
|
||||
}
|
||||
|
||||
@@ -1,4 +1,5 @@
|
||||
//! Prune current and legacy diagnostic logs immediately, then on a timer.
|
||||
//! Legacy cleanup continues when current diagnostics are unavailable.
|
||||
//! SQLite keeps freed pages for reuse.
|
||||
|
||||
use super::StateRuntime;
|
||||
@@ -26,7 +27,8 @@ impl StateRuntime {
|
||||
let Some(runtime) = runtime.upgrade() else {
|
||||
break;
|
||||
};
|
||||
if runtime.logs_pool.is_closed() {
|
||||
let logs_pool = runtime.logs_pool.as_deref();
|
||||
if runtime.pool.is_closed() || logs_pool.is_some_and(SqlitePool::is_closed) {
|
||||
break;
|
||||
}
|
||||
// Older versions write logs in sqlite_home. Keep the same retention policy
|
||||
@@ -38,8 +40,7 @@ impl StateRuntime {
|
||||
None
|
||||
}
|
||||
};
|
||||
for pool in std::iter::once(runtime.logs_pool.as_ref()).chain(legacy_pool.as_ref())
|
||||
{
|
||||
for pool in logs_pool.into_iter().chain(legacy_pool.as_ref()) {
|
||||
if let Err(err) = prune_by_age_and_size(
|
||||
pool,
|
||||
Utc::now().timestamp(),
|
||||
|
||||
@@ -94,55 +94,70 @@ async fn stops_at_one_second_when_recent_rows_exceed_budget() {
|
||||
|
||||
#[tokio::test]
|
||||
async fn periodic_cleanup_prunes_without_new_log_writes_or_restart() {
|
||||
let directory = super::super::test_support::unique_temp_dir();
|
||||
let sqlite = SqliteConfig::new_for_testing(directory.as_path().abs());
|
||||
let runtime = StateRuntime::init(
|
||||
sqlite.clone().with_local_logs_home(directory.join("log")),
|
||||
"test-provider".to_string(),
|
||||
)
|
||||
.await
|
||||
.unwrap();
|
||||
// An older process can create the legacy database after the new runtime starts.
|
||||
let legacy_pool = sqlite
|
||||
.open_logs_db(&LOGS_MIGRATOR, /*telemetry_override*/ None)
|
||||
for current_logs_available in [true, false] {
|
||||
let directory = super::super::test_support::unique_temp_dir();
|
||||
let sqlite = SqliteConfig::new_for_testing(directory.as_path().abs());
|
||||
let logs_home = directory.join("log");
|
||||
if !current_logs_available {
|
||||
std::fs::create_dir_all(&directory).unwrap();
|
||||
std::fs::write(&logs_home, "not a directory").unwrap();
|
||||
}
|
||||
let runtime = StateRuntime::init(
|
||||
sqlite.clone().with_local_logs_home(logs_home),
|
||||
"test-provider".to_string(),
|
||||
)
|
||||
.await
|
||||
.unwrap();
|
||||
runtime.start_periodic_logs_maintenance(Duration::from_millis(10));
|
||||
let now = Utc::now().timestamp();
|
||||
for round in 1..=2 {
|
||||
for pool in [runtime.logs_pool.as_ref(), &legacy_pool] {
|
||||
for timestamp in [now - 11 * DAY, now] {
|
||||
sqlx::query(
|
||||
"INSERT INTO logs (ts, ts_nanos, level, target) VALUES (?, 0, 'INFO', 'test')",
|
||||
)
|
||||
.bind(timestamp)
|
||||
.execute(pool)
|
||||
.await
|
||||
.unwrap();
|
||||
}
|
||||
}
|
||||
tokio::time::timeout(Duration::from_secs(5), async {
|
||||
loop {
|
||||
let current: Vec<i64> = sqlx::query_scalar("SELECT ts FROM logs ORDER BY ts")
|
||||
.fetch_all(runtime.logs_pool.as_ref())
|
||||
assert_eq!(runtime.logs_pool.is_some(), current_logs_available);
|
||||
// An older process can create the legacy database after the new runtime starts.
|
||||
let legacy_pool = sqlite
|
||||
.open_logs_db(&LOGS_MIGRATOR, /*telemetry_override*/ None)
|
||||
.await
|
||||
.unwrap();
|
||||
runtime.start_periodic_logs_maintenance(Duration::from_millis(10));
|
||||
let now = Utc::now().timestamp();
|
||||
for round in 1..=2 {
|
||||
let pools: Vec<_> = runtime
|
||||
.logs_pool
|
||||
.as_deref()
|
||||
.into_iter()
|
||||
.chain([&legacy_pool])
|
||||
.collect();
|
||||
for pool in &pools {
|
||||
for timestamp in [now - 11 * DAY, now] {
|
||||
sqlx::query(
|
||||
"INSERT INTO logs (ts, ts_nanos, level, target) VALUES (?, 0, 'INFO', 'test')",
|
||||
)
|
||||
.bind(timestamp)
|
||||
.execute(*pool)
|
||||
.await
|
||||
.unwrap();
|
||||
let legacy: Vec<i64> = sqlx::query_scalar("SELECT ts FROM logs ORDER BY ts")
|
||||
.fetch_all(&legacy_pool)
|
||||
.await
|
||||
.unwrap();
|
||||
if (current, legacy) == (vec![now; round], vec![now; round]) {
|
||||
break;
|
||||
}
|
||||
tokio::time::sleep(Duration::from_millis(10)).await;
|
||||
}
|
||||
})
|
||||
.await
|
||||
.expect("periodic cleanup should remove expired logs from both locations while idle");
|
||||
tokio::time::timeout(Duration::from_secs(5), async {
|
||||
loop {
|
||||
let mut retained = Vec::new();
|
||||
for pool in &pools {
|
||||
retained.push(
|
||||
sqlx::query_scalar::<_, i64>("SELECT ts FROM logs ORDER BY ts")
|
||||
.fetch_all(*pool)
|
||||
.await
|
||||
.unwrap(),
|
||||
);
|
||||
}
|
||||
if retained == vec![vec![now; round]; pools.len()] {
|
||||
break;
|
||||
}
|
||||
tokio::time::sleep(Duration::from_millis(10)).await;
|
||||
}
|
||||
})
|
||||
.await
|
||||
.expect("periodic cleanup should remove expired logs from both locations while idle");
|
||||
}
|
||||
legacy_pool.close().await;
|
||||
runtime.close().await;
|
||||
tokio::fs::remove_dir_all(directory).await.unwrap();
|
||||
}
|
||||
legacy_pool.close().await;
|
||||
runtime.close().await;
|
||||
tokio::fs::remove_dir_all(directory).await.unwrap();
|
||||
}
|
||||
|
||||
#[tokio::test]
|
||||
@@ -183,12 +198,12 @@ async fn legacy_writer_does_not_block_current_cleanup_and_is_retried() -> anyhow
|
||||
)
|
||||
.await?;
|
||||
sqlx::query("INSERT INTO logs (ts, ts_nanos, level, target) VALUES (0, 0, 'INFO', 'test')")
|
||||
.execute(runtime.logs_pool.as_ref())
|
||||
.execute(runtime.diagnostic_logs_pool().unwrap())
|
||||
.await?;
|
||||
runtime.start_periodic_logs_maintenance(Duration::from_millis(10));
|
||||
tokio::time::timeout(Duration::from_secs(5), async {
|
||||
while sqlx::query_scalar::<_, i64>("SELECT COUNT(*) FROM logs")
|
||||
.fetch_one(runtime.logs_pool.as_ref())
|
||||
.fetch_one(runtime.diagnostic_logs_pool().unwrap())
|
||||
.await
|
||||
.unwrap()
|
||||
!= 0
|
||||
@@ -263,7 +278,7 @@ async fn startup_cleanup_runs_without_waiting_for_the_period() {
|
||||
tokio::time::timeout(Duration::from_secs(5), async {
|
||||
loop {
|
||||
let current: i64 = sqlx::query_scalar("SELECT COUNT(*) FROM logs")
|
||||
.fetch_one(runtime.logs_pool.as_ref())
|
||||
.fetch_one(runtime.diagnostic_logs_pool().unwrap())
|
||||
.await
|
||||
.unwrap();
|
||||
let legacy: i64 = sqlx::query_scalar("SELECT COUNT(*) FROM logs")
|
||||
|
||||
@@ -1265,7 +1265,7 @@ ON CONFLICT(id) DO UPDATE SET
|
||||
for (thread_id, thread_id_string) in thread_ids.iter().zip(&thread_id_strings) {
|
||||
sqlx::query("DELETE FROM logs WHERE thread_id = ?")
|
||||
.bind(thread_id_string)
|
||||
.execute_with_busy_retry(self.logs_pool.as_ref())
|
||||
.execute_with_busy_retry(self.diagnostic_logs_pool()?)
|
||||
.await?;
|
||||
self.thread_queue.delete_thread_queue(*thread_id).await?;
|
||||
self.delete_versioned_thread_memory(*thread_id).await?;
|
||||
@@ -2254,7 +2254,7 @@ mod tests {
|
||||
.await?;
|
||||
seed_thread_cleanup_state(&runtime, thread_id, child_thread_id).await?;
|
||||
|
||||
runtime.logs_pool.close().await;
|
||||
runtime.diagnostic_logs_pool().unwrap().close().await;
|
||||
runtime
|
||||
.delete_thread(thread_id)
|
||||
.await
|
||||
@@ -2291,7 +2291,7 @@ mod tests {
|
||||
.await?;
|
||||
sqlx::query("INSERT INTO logs (ts, ts_nanos, level, target, feedback_log_body, thread_id) VALUES (1, 0, 'INFO', 'test', 'feedback log', ?)")
|
||||
.bind(thread_id.to_string())
|
||||
.execute(runtime.logs_pool.as_ref())
|
||||
.execute(runtime.diagnostic_logs_pool().unwrap())
|
||||
.await?;
|
||||
Ok(())
|
||||
}
|
||||
|
||||
@@ -88,11 +88,18 @@ async fn configured_log_directory_is_initialized_on_use_and_retries_after_failur
|
||||
// Opening unrelated state must not require the configured logs directory.
|
||||
let pool = sqlite.open_read_write_pool(&sqlite.state_db_path()).await?;
|
||||
pool.close().await;
|
||||
let runtime = crate::StateRuntime::init(sqlite.clone(), "openai".to_string()).await?;
|
||||
runtime.get_backfill_state().await?;
|
||||
assert!(
|
||||
crate::StateRuntime::init(sqlite.clone(), "openai".to_string())
|
||||
runtime
|
||||
.max_log_id(&crate::LogQuery::default())
|
||||
.await
|
||||
.is_err()
|
||||
);
|
||||
assert!(sqlite.goals_db_path().is_file());
|
||||
assert!(sqlite.memories_db_path().is_file());
|
||||
assert!(sqlite.queue_db_path().is_file());
|
||||
runtime.close().await;
|
||||
assert!(!fallback_logs_path.exists());
|
||||
|
||||
// A failed initialization must remain retryable without replacing the config.
|
||||
|
||||
Reference in New Issue
Block a user