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`
This commit is contained in:
Michael Bolin
2026-06-26 18:19:56 -07:00
committed by GitHub
Unverified
parent 3ae0543fdd
commit 4f1b5a4b73
8 changed files with 125 additions and 8 deletions
+1
View File
@@ -2316,6 +2316,7 @@ name = "codex-cli"
version = "0.0.0"
dependencies = [
"anyhow",
"app_test_support",
"assert_cmd",
"assert_matches",
"clap",
+13 -8
View File
@@ -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"
);
}
});
@@ -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<Value> {
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::<Value>)
.collect::<serde_json::Result<Vec<_>>>()
.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"],
}))
}
+2
View File
@@ -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;
@@ -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(())
}
+1
View File
@@ -1,5 +1,6 @@
mod auth;
mod conversation_summary;
mod fuzzy_file_search;
mod logging;
mod strict_config;
mod v2;
+1
View File
@@ -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 }
+25
View File
@@ -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<assert_cmd::Command> {
@@ -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(())
}