Devblog · 2026-06-26

Capping the SQLite log firehose

Five commits that drained Codex’s persistent log sink — and the bridged-target bug that made the obvious fix a silent no-op.
Date 2026-06-26 Status Shipped Issue #28224

What We Worked On

Codex keeps a local, persistent log sink: a SQLite database (logs_2.sqlite) written by a tracing layer in codex-rs/state/src/log_db.rs. It is a ring of fixed-size partitions — the layer inserts rows and prunes old ones to stay under a per-partition budget of 1,000 rows. That design is fine until something writes to it faster than a human ever reads it. Then the partition fills “in seconds” (the commit authors’ measurement) and the sink degrades into continuous insert-and-prune churn: every useful diagnostic is shoved out of the window by dependency noise before anyone can look at it.

That was issue #28224. This devblog walks the five commits that drained the firehose, in the order they landed. Three are upstream (jif@openai), pulled in through the Merge upstream/main into custom merge on 2026-06-25; two are local additions on the custom branch (philipbawn) — a regression test and the final INFO cap that closed the issue out.

Scope

Everything here touches one thing only: what gets persisted to the local SQLite ring. default_filter() is the log_db layer filter, so console output and RUST_LOG are unaffected, and the remote OpenTelemetry export plus all metrics are untouched.

The arc is worth naming up front, because each commit fixed a leak the previous one revealed:

  1. 1
    91e6da9

    Stop generating three log records per WebSocket event.

  2. 2
    e98d43a

    Introduce a shared filter that turns the noisy targets OFF.

  3. 3
    63f8f54

    Discover the OFF filter didn’t actually catch bridged events, and reject them inside the sink.

  4. 4
    fef76c4

    Lock the behavior down with regression tests.

  5. 5
    a0e8bee

    Cap the remaining default at INFO, because everything still defaulted to TRACE.

Commit 1 — Stop logging every Responses WebSocket event

91e6da9 (#29432) removed the single largest source. Every successful Responses WebSocket event was producing three local records: the full payload at TRACE, an OpenTelemetry log event, and an OpenTelemetry trace event (codex.websocket_event). On a busy thread that is the entire partition budget spent on routine success.

The fix removes the per-event TRACE payload line and stops emitting the codex.websocket_event log/trace pair, while keeping the counters, duration, and response-timing metrics, plus all parsing and error handling. The second hunk isn’t only a deletion — collapsing the per-arm error_message bookkeeping let the match arms fold together, which is why Binary/Close/Frame and Err(_) | None | Err(_) merge.

diff --git a/codex-rs/codex-api/src/endpoint/responses_websocket.rs b/codex-rs/codex-api/src/endpoint/responses_websocket.rs index fa01530102..d1f06ee2f8 100644 --- a/codex-rs/codex-api/src/endpoint/responses_websocket.rs +++ b/codex-rs/codex-api/src/endpoint/responses_websocket.rs @@ -668,7 +668,6 @@ async fn run_websocket_response_stream( match message { Message::Text(text) => { - trace!("websocket event: {text}"); if let Some(wrapped_error) = parse_wrapped_websocket_error_event(&text) && let Some(error) = map_wrapped_websocket_error_event(wrapped_error, text.to_string())
diff --git a/codex-rs/otel/src/events/session_telemetry.rs b/codex-rs/otel/src/events/session_telemetry.rs index c8e35b9f7d..efff5c24e3 100644 --- a/codex-rs/otel/src/events/session_telemetry.rs +++ b/codex-rs/otel/src/events/session_telemetry.rs @@ -707,7 +707,6 @@ impl SessionTelemetry { duration: Duration, ) { let mut kind = None; - let mut error_message = None; let mut success = true; match result { @@ -724,49 +723,26 @@ impl SessionTelemetry { } if kind.as_deref() == Some("response.failed") { success = false; - error_message = value - .get("response") - .and_then(|value| value.get("error")) - .map(serde_json::Value::to_string) - .or_else(|| Some("response.failed event received".to_string())); } } - Err(err) => { + Err(_) => { kind = Some("parse_error".to_string()); - error_message = Some(err.to_string()); success = false; } } } - tokio_tungstenite::tungstenite::Message::Binary(_) => { - success = false; - error_message = Some("unexpected binary websocket event".to_string()); - } tokio_tungstenite::tungstenite::Message::Ping(_) | tokio_tungstenite::tungstenite::Message::Pong(_) => { return; } - tokio_tungstenite::tungstenite::Message::Close(_) => { + tokio_tungstenite::tungstenite::Message::Binary(_) + | tokio_tungstenite::tungstenite::Message::Close(_) + | tokio_tungstenite::tungstenite::Message::Frame(_) => { success = false; - error_message = - Some("websocket closed by server before response.completed".to_string()); - } - tokio_tungstenite::tungstenite::Message::Frame(_) => { - success = false; - error_message = Some("unexpected websocket frame".to_string()); } }, - Ok(Some(Err(err))) => { + Ok(Some(Err(_))) | Ok(None) | Err(_) => { success = false; - error_message = Some(err.to_string()); - } - Ok(None) => { - success = false; - error_message = Some("stream closed before response.completed".to_string()); - } - Err(err) => { - success = false; - error_message = Some(err.to_string()); } } @@ -775,18 +751,6 @@ impl SessionTelemetry { let tags = [("kind", kind_str), ("success", success_str)]; self.counter(WEBSOCKET_EVENT_COUNT_METRIC, /*inc*/ 1, &tags); self.record_duration(WEBSOCKET_EVENT_DURATION_METRIC, duration, &tags); - log_and_trace_event!( - self, - common: { - event.name = "codex.websocket_event", - event.kind = %kind_str, - duration_ms = %duration.as_millis(), - success = success_str, - error.message = error_message.as_deref(), - }, - log: {}, - trace: {}, - ); } pub fn log_sse_event<E>(

Commit 2 — Filter noisy targets from persistent logs

e98d43a (#29457). Before this, both the app-server and the TUI built the log_db layer filter inline and identically: Targets::new().with_default(Level::TRACE) — i.e. persist everything from everyone at TRACE. This commit factors that into a single default_filter() in log_db.rs and uses it as the place to encode exclusions: target=log (the tracing-log bridge for dependency log-crate records), codex_otel.log_only, and codex_otel.trace_safe (the two OTEL mirror targets that duplicate events already exported remotely) all go to OFF. Everything else still defaulted to TRACE at this point — that’s the loose end commit 5 ties off.

diff --git a/codex-rs/state/src/log_db.rs b/codex-rs/state/src/log_db.rs index 71d2afbc01..55de2a3077 100644 --- a/codex-rs/state/src/log_db.rs +++ b/codex-rs/state/src/log_db.rs @@ -30,11 +30,13 @@ use tokio::sync::oneshot; use tracing::Event; use tracing::field::Field; use tracing::field::Visit; +use tracing::level_filters::LevelFilter; use tracing::span::Attributes; use tracing::span::Id; use tracing::span::Record; use tracing_subscriber::Layer; use tracing_subscriber::field::RecordFields; +use tracing_subscriber::filter::Targets; use tracing_subscriber::fmt::FormatFields; use tracing_subscriber::fmt::FormattedFields; use tracing_subscriber::fmt::format::DefaultFields; @@ -48,6 +50,14 @@ const LOG_QUEUE_CAPACITY: usize = 512; const LOG_BATCH_SIZE: usize = 128; const LOG_FLUSH_INTERVAL: Duration = Duration::from_secs(2); +pub fn default_filter() -> Targets { + Targets::new() + .with_default(LevelFilter::TRACE) + .with_target("log", LevelFilter::OFF) + .with_target("codex_otel.log_only", LevelFilter::OFF) + .with_target("codex_otel.trace_safe", LevelFilter::OFF) +} + #[derive(Clone, Copy, Debug, Eq, PartialEq)] pub struct LogSinkQueueConfig { pub queue_capacity: usize,
diff --git a/codex-rs/app-server/src/lib.rs b/codex-rs/app-server/src/lib.rs index f4cd83d732..264c28e098 100644 --- a/codex-rs/app-server/src/lib.rs +++ b/codex-rs/app-server/src/lib.rs @@ -68,13 +68,11 @@ use tokio::sync::mpsc; use tokio::sync::oneshot; use tokio::task::JoinHandle; use tokio_util::sync::CancellationToken; -use tracing::Level; use tracing::error; use tracing::info; use tracing::warn; use tracing_subscriber::EnvFilter; use tracing_subscriber::Layer; -use tracing_subscriber::filter::Targets; use tracing_subscriber::layer::SubscriberExt; use tracing_subscriber::registry::Registry; use tracing_subscriber::util::SubscriberInitExt; @@ -666,7 +664,7 @@ pub async fn run_main_with_transport_options( let log_db = state_db.clone().map(log_db::start); let log_db_layer = log_db .clone() - .map(|layer| layer.with_filter(Targets::new().with_default(Level::TRACE))); + .map(|layer| layer.with_filter(log_db::default_filter())); let otel_logger_layer = otel.as_ref().and_then(|o| o.logger_layer()); let otel_tracing_layer = otel.as_ref().and_then(|o| o.tracing_layer()); let _ = tracing_subscriber::registry()
diff --git a/codex-rs/tui/src/lib.rs b/codex-rs/tui/src/lib.rs index 9a4a88c86d..c5cf1e1853 100644 --- a/codex-rs/tui/src/lib.rs +++ b/codex-rs/tui/src/lib.rs @@ -74,12 +74,10 @@ use std::path::PathBuf; use std::sync::Arc; use std::time::Instant; pub use token_usage::TokenUsage; -use tracing::Level; use tracing::error; use tracing::warn; use tracing_appender::non_blocking; use tracing_subscriber::EnvFilter; -use tracing_subscriber::filter::Targets; use tracing_subscriber::prelude::*; use url::Url; use uuid::Uuid; @@ -1232,7 +1230,7 @@ pub async fn run_main( let log_db = state_db.clone().map(log_db::start); let log_db_layer = log_db .clone() - .map(|layer| layer.with_filter(Targets::new().with_default(Level::TRACE))); + .map(|layer| layer.with_filter(log_db::default_filter())); let _ = tracing_subscriber::registry() .with(tui_file_layer)

Commit 3 — Stop persisting bridged log events

63f8f54 (#29599) is the subtle one, and the reason the campaign needed more than a filter. with_target("log", OFF) looks like it should suppress the log-crate bridge — but it doesn’t.

The blind spot

tracing-log evaluates filters against the original dependency target (hyper, opentelemetry, …) before re-emitting the record with the tracing target log. By the time the record carries target = "log", the filter has already let it through under its real name. So high-volume dependency TRACE kept reaching SQLite despite the OFF directive.

The fix stops trusting the filter for this case and rejects the bridged record inside the sink’s on_event, before any formatting or queueing. (The opentelemetry_sdk DEBUG-timer guard just below it is pre-existing — the commit message notes those meta-events were once >30% of retained logs.)

diff --git a/codex-rs/state/src/log_db.rs b/codex-rs/state/src/log_db.rs index 55de2a3077..2cf0f5d9af 100644 --- a/codex-rs/state/src/log_db.rs +++ b/codex-rs/state/src/log_db.rs @@ -199,6 +199,13 @@ where fn on_event(&self, event: &Event<'_>, ctx: tracing_subscriber::layer::Context<'_, S>) { let metadata = event.metadata(); + // `tracing-log` checks filters with the original log target before + // dispatching an event whose tracing target is `log`, so the outer + // target filter cannot reliably reject these bridged events. + if metadata.target() == "log" { + return; + } + // The SDK emits DEBUG timer meta-events every second per process; these // were over 30% of retained logs in measured high-fanout Codex environments. if metadata.target() == "opentelemetry_sdk"

Commit 4 — Add SQLite log filter regressions

fef76c4. With three behavioral fixes in place, the next local commit pinned them down. Two tests: one asserts default_filter() excludes the #28224 noisy targets (and still admits ordinary targets like codex_state); the other is the important end-to-end one — it wires the real sink behind a deliberately permissive with_default(TRACE) filter, emits a bridged target: "log" TRACE and a codex_state INFO, flushes, and asserts only the codex_state row survives in the DB. That test is what would catch a regression of commit 3 even if someone “fixed” the filter to allow log through again.

diff --git a/codex-rs/state/src/log_db_filter_tests.rs b/codex-rs/state/src/log_db_filter_tests.rs index 36ee27aba8..de8f1c3037 100644 --- a/codex-rs/state/src/log_db_filter_tests.rs +++ b/codex-rs/state/src/log_db_filter_tests.rs @@ -6,6 +6,59 @@ use uuid::Uuid; use super::*; +#[test] +fn default_filter_excludes_issue_28224_noisy_targets() { + let filter = default_filter(); + + assert!(!filter.would_enable("log", &tracing::Level::TRACE)); + assert!(!filter.would_enable("codex_otel.log_only", &tracing::Level::INFO)); + assert!(!filter.would_enable("codex_otel.trace_safe", &tracing::Level::INFO)); + assert!(!filter.would_enable("codex_otel.trace_safe.summary", &tracing::Level::INFO)); + + assert!(filter.would_enable("codex_state", &tracing::Level::TRACE)); +} + +#[tokio::test] +async fn sqlite_sink_drops_bridged_log_target_even_when_layer_filter_allows_it() { + let codex_home = + std::env::temp_dir().join(format!("codex-state-log-db-filter-{}", Uuid::new_v4())); + let runtime = StateRuntime::init(codex_home.clone(), "test-provider".to_string()) + .await + .expect("initialize runtime"); + let layer = start(runtime.clone()); + + let guard = tracing_subscriber::registry() + .with( + layer + .clone() + .with_filter(Targets::new().with_default(tracing::Level::TRACE)), + ) + .set_default(); + + tracing::trace!(target: "log", "dropped-bridged-log"); + tracing::info!(target: "codex_state", "retained-info"); + + layer.flush().await; + drop(guard); + + let logs = runtime + .query_logs(&crate::LogQuery::default()) + .await + .expect("query logs after flush"); + assert_eq!( + logs.iter() + .map(|row| ( + row.level.as_str(), + row.target.as_str(), + row.message.as_deref() + )) + .collect::<Vec<_>>(), + vec![("INFO", "codex_state", Some("retained-info"))] + ); + + let _ = tokio::fs::remove_dir_all(codex_home).await; +} + #[tokio::test] async fn sqlite_sink_drops_low_level_opentelemetry_sdk_logs() { let codex_home =

Commit 5 — Cap the persistent sink at INFO

a0e8bee is the loose end. After the three explicitly-OFF targets were handled, default_filter() still said .with_default(LevelFilter::TRACE). That meant the remaining write-amplification was ordinary TRACE/DEBUG chatter from everything that wasn’t named: dependencies like hyper_util and opentelemetry-*, and chatty internal targets — codex_api::sse, codex_mcp::connection_manager, codex_app_server::outgoing_message, codex_tui::markdown_stream. None of it is worth a partition slot in the persistent ring.

Capping the default at INFO keeps useful diagnostics (warnings, errors, and deliberate INFO breadcrumbs) while dropping the firehose. The regression test is updated from “ordinary targets keep TRACE” to the new contract: INFO is captured, TRACE is dropped.

diff --git a/codex-rs/state/src/log_db.rs b/codex-rs/state/src/log_db.rs index 2cf0f5d9af..036a74ace7 100644 --- a/codex-rs/state/src/log_db.rs +++ b/codex-rs/state/src/log_db.rs @@ -51,8 +51,13 @@ const LOG_BATCH_SIZE: usize = 128; const LOG_FLUSH_INTERVAL: Duration = Duration::from_secs(2); pub fn default_filter() -> Targets { + // Persist INFO and above by default. TRACE/DEBUG from dependencies (hyper, + // opentelemetry) and chatty internal targets (codex_api::sse, MCP/app-server + // wire traffic) were the bulk of the #28224 write-amplification once the three + // explicitly-OFF targets below were handled; capping the default keeps useful + // diagnostics while dropping that firehose from the SQLite sink. Targets::new() - .with_default(LevelFilter::TRACE) + .with_default(LevelFilter::INFO) .with_target("log", LevelFilter::OFF) .with_target("codex_otel.log_only", LevelFilter::OFF) .with_target("codex_otel.trace_safe", LevelFilter::OFF)
diff --git a/codex-rs/state/src/log_db_filter_tests.rs b/codex-rs/state/src/log_db_filter_tests.rs index de8f1c3037..c8c74720e1 100644 --- a/codex-rs/state/src/log_db_filter_tests.rs +++ b/codex-rs/state/src/log_db_filter_tests.rs @@ -15,7 +15,10 @@ fn default_filter_excludes_issue_28224_noisy_targets() { assert!(!filter.would_enable("codex_otel.trace_safe", &tracing::Level::INFO)); assert!(!filter.would_enable("codex_otel.trace_safe.summary", &tracing::Level::INFO)); - assert!(filter.would_enable("codex_state", &tracing::Level::TRACE)); + // Ordinary targets are captured at INFO and above, but their TRACE/DEBUG + // chatter is dropped from the persistent log by the INFO default. + assert!(filter.would_enable("codex_state", &tracing::Level::INFO)); + assert!(!filter.would_enable("codex_state", &tracing::Level::TRACE)); } #[tokio::test]

The Net Result

default_filter() now reads, end to end:

pub fn default_filter() -> Targets { Targets::new() .with_default(LevelFilter::INFO) .with_target("log", LevelFilter::OFF) .with_target("codex_otel.log_only", LevelFilter::OFF) .with_target("codex_otel.trace_safe", LevelFilter::OFF) }

…backstopped by the in-sink if metadata.target() == "log" { return; } guard for the bridge that the filter alone can’t catch. The persistent SQLite ring keeps INFO-and-above from real targets, with the bridged log firehose and the two OTEL mirror targets gone, and the busiest single source (per-event WebSocket logging) removed at the point of emission.

What Went Well

Each commit was a clean layer of the same onion. Reduce emission → filter targets → fix the filter’s blind spot → test it → cap the rest. No commit undid an earlier one; each addressed a leak the previous one exposed.

The bridge bug was diagnosed, not patched over. It would have been easy to shrug at “the OFF directive doesn’t work” and crank thresholds. Instead 63f8f54 names why (tracing-log filters on the original target) and fixes it at the right layer — inside the sink, where the bridged target is finally visible.

The regression test exercises the real sink, not just the filter object. sqlite_sink_drops_bridged_log_target_even_when_layer_filter_allows_it deliberately allows everything at the filter and still asserts the bridged row never lands in the DB. That is testing the guard, not the directive.

What Didn’t Go Well

The OFF directive was a false sense of security for a full commit. #29457 shipped believing target=log was disabled; #29599 had to follow up once it was clear bridged events still reached SQLite. The filter looked correct and wasn’t, which is the most expensive kind of wrong.

The default sat at TRACE through four commits. Three targets were named and silenced while the catch-all stayed at TRACE, so unnamed dependency and internal chatter kept amplifying writes until a0e8bee. The real fix — “stop persisting TRACE you never asked for” — was also the last to land.

Caveat

The performance numbers are reported, not reproduced here. “Fills in seconds” and “>30% of retained logs” come from the commit authors’ measured environments; this writeup confirms the code changes from the diffs, not those magnitudes independently.

Takeaways

  1. 1
    A filter directive is a claim, not a guarantee — confirm where the record is actually evaluated.

    with_target("log", OFF) reads as “no log events,” but the bridge is filtered under its original target first. When a suppression rule sits upstream of a re-targeting layer, it can silently no-op.

  2. 2
    The cheapest log to store is the one you never emit.

    The biggest single win (91e6da9) wasn’t a filter at all — it was deleting three records per WebSocket event at the source. Filter tuning is downstream cleanup; emission discipline is the dam.

  3. 3
    A bounded, self-pruning sink turns volume into silent data loss.

    A fixed 1,000-row partition doesn’t error when flooded — it quietly evicts the signal. “Why is my log empty right after the interesting thing happened?” is the failure mode, and it argues for filtering aggressively by default.

  4. 4
    Default to INFO for persistent local sinks; opt into TRACE deliberately.

    with_default(TRACE) for a durable store means every dependency’s debug chatter is your problem forever. Make the floor INFO and let operators raise it.

  5. 5
    Pin subtle filter behavior with an end-to-end test, not a unit assertion on the filter object.

    The filter can pass would_enable checks and still be bypassed by a bridge; only a test that drives the real sink proves the row doesn’t land.

The Watercolor

I’d paint this one as a dam being built across a river at night, in four narrowing courses of stone, and I’d start with the water.

The first wash is a torrent — Payne’s grey and indigo poured wet-into-wet from the top of the sheet, no drawing underneath, just volume. That’s the log firehose: three records per heartbeat, a thousand-row pool that refills before the surface can settle. Down in the pool I’d drop a few flecks of cadmium and viridian — the useful diagnostics — and then let the grey roll right over them so you can barely find them again. That’s the whole problem in one gesture: the signal is in there, drowning.

Then the masonry, course by course, each a drier stroke than the last. The first stone is broad and confident — stop emitting — and the water visibly drops behind it. The second course looks solid but I’d paint one stone slightly the wrong color, a hair too warm, because it didn’t actually seal: the bridged water seeps under it, a thin ribbon of the original indigo finding the gap. The third course is the patient one — someone knelt down, found the seep, understood that the water was being measured by its old name before it was relabeled, and set the stone under the leak instead of over it. I’d render that stone in the most deliberate dry-brush on the page, every edge intentional.

The fourth course is almost nothing — a single low line of INFO-grey — but it’s what finally brings the water down to a readable level. Behind the finished dam the pool goes still and clear, and now you can see the cadmium and viridian flecks resting on the bottom, exactly where they were the whole time, finally legible.

The brushwork tells the honest story: bold and fast where deletion did the heavy lifting, one too-warm stone where the filter only looked sealed, and the calmest, most careful strokes saved for the small fix that mattered most. I’d title it The Pool Goes Clear When You Stop Pouring.