From 4f1b5a4b734da8f159e1b727042b4534ed091307 Mon Sep 17 00:00:00 2001 From: Michael Bolin Date: Fri, 26 Jun 2026 18:19:56 -0700 Subject: [PATCH] app-server: structure and test JSON shutdown logs (#30314) ## Why `LOG_FORMAT=json` and `RUST_LOG` are supported by app-server, but the behavior was only covered indirectly. We should verify the actual JSONL written by both user-facing entry points: `codex app-server` and the standalone `codex-app-server` binary. The existing processor shutdown message also always said the channel closed, even though the processor can exit for several different reasons. Structured fields make that event more accurate and useful to log consumers. ## What changed - Record the processor `exit_reason`, remaining connection count, and forced-shutdown state as structured tracing fields. - Add a shared process-test helper that enables JSON logging, validates every stderr line as JSON, and verifies the top-level timestamp is RFC 3339. - Cover both `codex app-server` and `codex-app-server`, asserting the stable `level`, `fields`, and `target` payload. ## Test plan - `just test -p codex-app-server standalone_app_server_emits_json_info_events` - `just test -p codex-cli app_server_emits_json_info_events` --- codex-rs/Cargo.lock | 1 + codex-rs/app-server/src/lib.rs | 21 ++++--- .../app-server/tests/common/json_logging.rs | 55 +++++++++++++++++++ codex-rs/app-server/tests/common/lib.rs | 2 + codex-rs/app-server/tests/suite/logging.rs | 27 +++++++++ codex-rs/app-server/tests/suite/mod.rs | 1 + codex-rs/cli/Cargo.toml | 1 + codex-rs/cli/tests/app_server.rs | 25 +++++++++ 8 files changed, 125 insertions(+), 8 deletions(-) create mode 100644 codex-rs/app-server/tests/common/json_logging.rs create mode 100644 codex-rs/app-server/tests/suite/logging.rs diff --git a/codex-rs/Cargo.lock b/codex-rs/Cargo.lock index bd194ece8..88601e938 100644 --- a/codex-rs/Cargo.lock +++ b/codex-rs/Cargo.lock @@ -2316,6 +2316,7 @@ name = "codex-cli" version = "0.0.0" dependencies = [ "anyhow", + "app_test_support", "assert_cmd", "assert_matches", "clap", diff --git a/codex-rs/app-server/src/lib.rs b/codex-rs/app-server/src/lib.rs index beed35848..0edb57d8a 100644 --- a/codex-rs/app-server/src/lib.rs +++ b/codex-rs/app-server/src/lib.rs @@ -912,7 +912,7 @@ pub async fn run_main_with_transport_options( async move { let mut listen_for_threads = true; let mut shutdown_state = ShutdownState::default(); - loop { + let exit_reason = loop { let running_turn_count = { let running_turn_count = running_turn_count_rx.borrow(); *running_turn_count @@ -925,7 +925,7 @@ pub async fn run_main_with_transport_options( let _ = outbound_control_tx .send(OutboundControlEvent::DisconnectAll) .await; - break; + break "shutdown_requested"; } tokio::select! { @@ -947,7 +947,7 @@ pub async fn run_main_with_transport_options( } event = transport_event_rx.recv() => { let Some(event) = event else { - break; + break "transport_channel_closed"; }; match event { TransportEvent::ConnectionOpened { @@ -977,7 +977,7 @@ pub async fn run_main_with_transport_options( .await .is_err() { - break; + break "outbound_router_closed"; } connections.insert( connection_id, @@ -1005,10 +1005,10 @@ pub async fn run_main_with_transport_options( .await; }); if !outbound_closed { - break; + break "outbound_router_closed"; } if shutdown_when_no_connections && connections.is_empty() { - break; + break "last_connection_closed"; } } TransportEvent::IncomingMessage { connection_id, message } => { @@ -1147,7 +1147,7 @@ pub async fn run_main_with_transport_options( } } } - } + }; if !shutdown_state.forced() { futures::future::join_all( @@ -1162,7 +1162,12 @@ pub async fn run_main_with_transport_options( } else { connection_cleanup_tasks.abort(); } - info!("processor task exited (channel closed)"); + info!( + exit_reason, + remaining_connection_count = connections.len(), + shutdown_forced = shutdown_state.forced(), + "processor task exited" + ); } }); diff --git a/codex-rs/app-server/tests/common/json_logging.rs b/codex-rs/app-server/tests/common/json_logging.rs new file mode 100644 index 000000000..c6c78bd0a --- /dev/null +++ b/codex-rs/app-server/tests/common/json_logging.rs @@ -0,0 +1,55 @@ +use std::path::Path; +use std::process::Command; +use std::process::Stdio; + +use anyhow::Context; +use anyhow::Result; +use serde_json::Value; +use serde_json::json; + +pub fn app_server_json_shutdown_event( + binary: &str, + args: &[&str], + codex_home: &Path, +) -> Result { + std::fs::write( + codex_home.join("config.toml"), + "[features]\nplugins = false\n", + )?; + let output = Command::new(codex_utils_cargo_bin::cargo_bin(binary)?) + .stdin(Stdio::null()) + .env("CODEX_HOME", codex_home) + .env( + "CODEX_APP_SERVER_MANAGED_CONFIG_PATH", + codex_home.join("managed_config.toml"), + ) + .env("LOG_FORMAT", "json") + .env("RUST_LOG", "codex_app_server=info") + .args(args) + .output()?; + + let stderr = String::from_utf8(output.stderr)?; + anyhow::ensure!(output.status.success(), "app-server failed: {stderr}"); + + let events = stderr + .lines() + .filter(|line| !line.is_empty()) + .map(serde_json::from_str::) + .collect::>>() + .with_context(|| format!("app-server stderr was not JSONL: {stderr}"))?; + let event = events + .iter() + .find(|event| event["fields"]["message"] == "processor task exited") + .context("missing INFO shutdown event in app-server JSON logs")?; + let timestamp = event["timestamp"] + .as_str() + .context("shutdown event did not include a timestamp")?; + chrono::DateTime::parse_from_rfc3339(timestamp) + .with_context(|| format!("shutdown event timestamp was not RFC 3339: {timestamp}"))?; + + Ok(json!({ + "level": event["level"], + "fields": event["fields"], + "target": event["target"], + })) +} diff --git a/codex-rs/app-server/tests/common/lib.rs b/codex-rs/app-server/tests/common/lib.rs index 76c4c85f2..fbc674806 100644 --- a/codex-rs/app-server/tests/common/lib.rs +++ b/codex-rs/app-server/tests/common/lib.rs @@ -3,6 +3,7 @@ mod analytics_server; mod auth_fixtures; mod config; +mod json_logging; mod mock_model_server; mod models_cache; mod responses; @@ -26,6 +27,7 @@ pub use core_test_support::test_absolute_path; pub use core_test_support::test_path_buf_with_windows; pub use core_test_support::test_tmp_path; pub use core_test_support::test_tmp_path_buf; +pub use json_logging::app_server_json_shutdown_event; pub use mock_model_server::create_mock_responses_server_repeating_assistant; pub use mock_model_server::create_mock_responses_server_sequence; pub use mock_model_server::create_mock_responses_server_sequence_unchecked; diff --git a/codex-rs/app-server/tests/suite/logging.rs b/codex-rs/app-server/tests/suite/logging.rs new file mode 100644 index 000000000..ea2c31a76 --- /dev/null +++ b/codex-rs/app-server/tests/suite/logging.rs @@ -0,0 +1,27 @@ +use anyhow::Result; +use app_test_support::app_server_json_shutdown_event; +use pretty_assertions::assert_eq; +use serde_json::json; +use tempfile::TempDir; + +#[test] +fn standalone_app_server_emits_json_info_events() -> Result<()> { + let codex_home = TempDir::new()?; + let event = app_server_json_shutdown_event("codex-app-server", &[], codex_home.path())?; + + assert_eq!( + event, + json!({ + "level": "INFO", + "fields": { + "message": "processor task exited", + "exit_reason": "last_connection_closed", + "remaining_connection_count": 0, + "shutdown_forced": false, + }, + "target": "codex_app_server", + }) + ); + + Ok(()) +} diff --git a/codex-rs/app-server/tests/suite/mod.rs b/codex-rs/app-server/tests/suite/mod.rs index bac309a93..09c40493f 100644 --- a/codex-rs/app-server/tests/suite/mod.rs +++ b/codex-rs/app-server/tests/suite/mod.rs @@ -1,5 +1,6 @@ mod auth; mod conversation_summary; mod fuzzy_file_search; +mod logging; mod strict_config; mod v2; diff --git a/codex-rs/cli/Cargo.toml b/codex-rs/cli/Cargo.toml index 7be1146df..9a8312ced 100644 --- a/codex-rs/cli/Cargo.toml +++ b/codex-rs/cli/Cargo.toml @@ -95,6 +95,7 @@ windows-sys = { version = "0.52", features = [ ] } [dev-dependencies] +app_test_support = { workspace = true } assert_cmd = { workspace = true } assert_matches = { workspace = true } codex-utils-cargo-bin = { workspace = true } diff --git a/codex-rs/cli/tests/app_server.rs b/codex-rs/cli/tests/app_server.rs index 4a2642379..6815c2be9 100644 --- a/codex-rs/cli/tests/app_server.rs +++ b/codex-rs/cli/tests/app_server.rs @@ -1,7 +1,10 @@ use std::path::Path; use anyhow::Result; +use app_test_support::app_server_json_shutdown_event; use predicates::str::contains; +use pretty_assertions::assert_eq; +use serde_json::json; use tempfile::TempDir; fn codex_command(codex_home: &Path) -> Result { @@ -28,3 +31,25 @@ foo = "bar" Ok(()) } + +#[test] +fn app_server_emits_json_info_events() -> Result<()> { + let codex_home = TempDir::new()?; + let event = app_server_json_shutdown_event("codex", &["app-server"], codex_home.path())?; + + assert_eq!( + event, + json!({ + "level": "INFO", + "fields": { + "message": "processor task exited", + "exit_reason": "last_connection_closed", + "remaining_connection_count": 0, + "shutdown_forced": false, + }, + "target": "codex_app_server", + }) + ); + + Ok(()) +}