diff --git a/codex-rs/app-server/tests/suite/logging.rs b/codex-rs/app-server/tests/suite/logging.rs index 1d6d49c777..ce75967b80 100644 --- a/codex-rs/app-server/tests/suite/logging.rs +++ b/codex-rs/app-server/tests/suite/logging.rs @@ -4,18 +4,24 @@ use app_test_support::ChatGptIdTokenClaims; use app_test_support::MockResponsesConfig; use app_test_support::TestAppServer; use app_test_support::app_server_json_shutdown_event; +use app_test_support::create_escalated_command_execution_sse_response; use app_test_support::create_exec_command_sse_response; use app_test_support::create_final_assistant_message_sse_response; use app_test_support::create_mock_responses_server_sequence; use app_test_support::encode_id_token; use app_test_support::write_models_cache; +use codex_app_server_protocol::ApprovalsReviewer; +use codex_app_server_protocol::AskForApproval; use codex_app_server_protocol::ClientInfo; use codex_app_server_protocol::ClientRequest; use codex_app_server_protocol::InitializeCapabilities; use codex_app_server_protocol::JSONRPCMessage; use codex_app_server_protocol::LoginAccountResponse; use codex_app_server_protocol::RequestId; +use codex_app_server_protocol::SandboxPolicy; use codex_app_server_protocol::ServerRequest; +use codex_app_server_protocol::ThreadApproveGuardianDeniedActionParams; +use codex_app_server_protocol::ThreadApproveGuardianDeniedActionResponse; use codex_app_server_protocol::ThreadStartParams; use codex_app_server_protocol::TurnStartParams; use codex_app_server_protocol::TurnStartResponse; @@ -27,6 +33,7 @@ use codex_state::StateRuntime; use codex_utils_absolute_path::test_support::PathExt; use core_test_support::responses; use core_test_support::skip_if_no_network; +use core_test_support::skip_if_wine_exec; use pretty_assertions::assert_eq; use serde_json::Value; use serde_json::json; @@ -48,6 +55,155 @@ use wiremock::matchers::path; const READ_TIMEOUT: Duration = Duration::from_secs(10); +#[tokio::test] +async fn submission_metadata_reaches_persisted_and_feedback_logs() -> Result<()> { + skip_if_wine_exec!( + Ok(()), + "command approval routing requires a host-native cwd under Wine-exec" + ); + skip_if_no_network!(Ok(())); + + let server = create_mock_responses_server_sequence(vec![ + create_escalated_command_execution_sse_response( + vec!["echo".into(), "hello".into()], + /*workdir*/ None, + /*timeout_ms*/ Some(5000), + "call-approval", + )?, + create_final_assistant_message_sse_response("done")?, + ]) + .await; + let codex_home = TempDir::new()?; + MockResponsesConfig::new(&server.uri()) + .with_approval_policy("on-request") + .with_provider_config("supports_websockets = false") + .write(codex_home.path())?; + let mut app_server = TestAppServer::builder() + .with_codex_home(codex_home.path()) + // SQLite and feedback diagnostics must remain safe independently of stderr. + .with_env_overrides(&[("RUST_LOG", Some("off"))]) + .build() + .await?; + app_server.initialize().await?; + let thread = app_server + .start_thread(ThreadStartParams::default()) + .await? + .thread; + let _: ThreadApproveGuardianDeniedActionResponse = app_server + .request( + |request_id| ClientRequest::ThreadApproveGuardianDeniedAction { + request_id, + params: ThreadApproveGuardianDeniedActionParams { + thread_id: thread.id.clone(), + event: json!({ + "id": "guardian-review", + "target_item_id": "guardian-item", + "turn_id": "guardian-turn", + "status": "denied", + "action": { + "type": "mcp_tool_call", + "server": "example", + "tool_name": "write", + }, + }), + }, + }, + ) + .await?; + let _: TurnStartResponse = app_server + .request(|request_id| ClientRequest::TurnStart { + request_id, + params: TurnStartParams { + thread_id: thread.id.clone(), + input: vec![UserInput::Text { + text: "run echo".into(), + text_elements: Vec::new(), + }], + approval_policy: Some(AskForApproval::OnRequest), + approvals_reviewer: Some(ApprovalsReviewer::User), + sandbox_policy: Some(SandboxPolicy::ReadOnly { + network_access: false, + }), + ..Default::default() + }, + }) + .await?; + let server_request = + timeout(READ_TIMEOUT, app_server.read_stream_until_request_message()).await??; + let ServerRequest::CommandExecutionRequestApproval { request_id, params } = server_request + else { + anyhow::bail!("expected command approval request"); + }; + let approval_id = params.approval_id.unwrap_or(params.item_id); + app_server + .send_response(request_id, json!({ "decision": "decline" })) + .await?; + timeout( + READ_TIMEOUT, + app_server.read_stream_until_notification_message("turn/completed"), + ) + .await??; + + let state = StateRuntime::init( + SqliteConfig::new_for_testing(codex_home.path().abs()), + "mock_provider".into(), + ) + .await?; + // Feedback is read from SQLite, so this also verifies persistence. + let feedback = timeout(Duration::from_secs(/*secs*/ 60), async { + loop { + let logs = + String::from_utf8(state.query_feedback_logs_for_threads(&[&thread.id]).await?)?; + if logs + .lines() + .any(|line| line.contains("Submission") && line.contains("exec_approval")) + { + break Ok::<_, anyhow::Error>(logs); + } + tokio::time::sleep(Duration::from_millis(/*millis*/ 50)).await; + } + }) + .await??; + state.close().await; + for (operation, fields) in [ + ( + "exec_approval", + vec![ + format!("thread_id={}", thread.id), + format!("id: \"{approval_id}\""), + format!("turn_id: Some(\"{}\")", params.turn_id), + "decision: denied".into(), + ], + ), + ( + "approve_guardian_denied_action", + vec![ + "review_id: \"guardian-review\"".into(), + "target_item_id: Some(\"guardian-item\")".into(), + "turn_id: \"guardian-turn\"".into(), + "status: Denied".into(), + ], + ), + ( + "turn_input", + vec![ + "approval_policy: Some(OnRequest)".into(), + "approvals_reviewer: Some(User)".into(), + "sandbox_policy: Some(read-only)".into(), + ], + ), + ] { + let line = feedback + .lines() + .find(|line| line.contains("Submission") && line.contains(operation)) + .with_context(|| format!("missing {operation} submission"))?; + for field in fields { + anyhow::ensure!(line.contains(&field), "missing {field}: {line}"); + } + } + Ok(()) +} + #[tokio::test] async fn credentials_stay_out_of_persisted_and_feedback_logs() -> Result<()> { skip_if_no_network!(Ok(())); diff --git a/codex-rs/core/src/session/handlers.rs b/codex-rs/core/src/session/handlers.rs index 32f1a7a73d..14f721d172 100644 --- a/codex-rs/core/src/session/handlers.rs +++ b/codex-rs/core/src/session/handlers.rs @@ -461,11 +461,15 @@ pub(super) async fn submission_loop( continue; } }; - if matches!(sub.op, Op::ResolveElicitation { .. }) { - debug!(submission_id = %sub.id, operation = sub.op.kind(), "Submission"); - } else { - debug!(?sub, "Submission"); - } + debug!( + thread_id = %sess.thread_id(), + submission_id = %sub.id, + operation = sub.op.kind(), + parent_turn_id = ?sub.parent_turn_id, + root_turn_id = ?sub.root_turn_id, + op = ?sub.op, + "Submission" + ); let dispatch_span = submission_dispatch_span(&sub); let should_exit = async { match sub.op { diff --git a/codex-rs/core/src/session/submission.rs b/codex-rs/core/src/session/submission.rs index 413e1874b1..b5649cf9de 100644 --- a/codex-rs/core/src/session/submission.rs +++ b/codex-rs/core/src/session/submission.rs @@ -6,7 +6,6 @@ use codex_protocol::protocol::W3cTraceContext; use tokio::sync::OwnedRwLockReadGuard; #[derive(Debug)] -#[expect(dead_code, reason = "Turn ancestry is retained in Debug diagnostics.")] pub(crate) struct Submission { pub id: String, pub op: Op, diff --git a/codex-rs/protocol/src/protocol.rs b/codex-rs/protocol/src/protocol.rs index bbabeacf7e..82f3c8f7b7 100644 --- a/codex-rs/protocol/src/protocol.rs +++ b/codex-rs/protocol/src/protocol.rs @@ -483,7 +483,17 @@ pub enum TurnSettingsUpdateOutcome { /// Thread-settings overrides that can be applied before user input or on their /// own. Standalone updates change the settings inherited by future turns. -#[derive(Debug, Clone, Default, PartialEq)] +// Diagnostics retain requested policy categories, never paths or instruction payloads. +#[derive(derive_more::Debug, Clone, Default, PartialEq)] +#[debug( + "ThreadSettingsOverrides {{ approval_policy: {approval_policy:?}, approvals_reviewer: {approvals_reviewer:?}, sandbox_policy: {:?}, permission_profile: {:?} }}", + sandbox_policy.as_ref().map(tracing::field::display), + permission_profile.as_ref().map(|profile| match profile { + PermissionProfile::Managed { .. } => "managed", + PermissionProfile::Disabled => "disabled", + PermissionProfile::External { .. } => "external", + }), +)] pub struct ThreadSettingsOverrides { /// Updated fallback `cwd` and environments supplied together as a complete pair. pub environments: Option, @@ -560,7 +570,8 @@ pub struct AdditionalContextEntry { } /// Submission operation -#[derive(Debug)] +// Keep diagnostic fields explicit so new payload fields do not enter logs by default. +#[derive(derive_more::Debug)] #[allow(clippy::large_enum_variant)] #[non_exhaustive] pub enum Op { @@ -570,6 +581,7 @@ pub enum Op { /// Interrupt the named turn only if no input is queued for it. /// The decision is acknowledged before cancellation finishes. + #[debug("InterruptIfNoPendingInput {{ turn_id: {turn_id:?} }}")] InterruptIfNoPendingInput { turn_id: String, reply: oneshot::Sender, @@ -580,15 +592,19 @@ pub enum Op { CleanBackgroundTerminals, /// Start a realtime conversation stream. + #[debug("RealtimeConversationStart {{ session_id: {:?}, version: {:?}, output_modality: {:?} }}", _0.realtime_session_id, _0.version, _0.output_modality)] RealtimeConversationStart(ConversationStartParams), /// Send audio input to the running realtime conversation stream. + #[debug("RealtimeConversationAudio {{ item_id: {:?}, sample_rate: {}, num_channels: {}, samples_per_channel: {:?} }}", _0.frame.item_id, _0.frame.sample_rate, _0.frame.num_channels, _0.frame.samples_per_channel)] RealtimeConversationAudio(ConversationAudioParams), /// Send text input to the running realtime conversation stream. + #[debug("RealtimeConversationText {{ role: {:?} }}", _0.role)] RealtimeConversationText(ConversationTextParams), /// Append speakable text to the running realtime conversation stream. + #[debug("RealtimeConversationSpeech")] RealtimeConversationSpeech(ConversationSpeechParams), /// Close the running realtime conversation stream. @@ -598,6 +614,7 @@ pub enum Op { RealtimeConversationListVoices, /// Submit turn input using the requested routing behavior. + #[debug("TurnInput {{ requested_settings: {:?} }}", request.thread_settings)] TurnInput { request: Box, mode: TurnInputMode, @@ -605,6 +622,7 @@ pub enum Op { }, /// Resume an interrupted regular turn. + #[debug("RecoverTurn {{ requested_settings: {thread_settings:?} }}")] RecoverTurn { thread_settings: ThreadSettingsOverrides, start_options: TurnStartOptions, @@ -612,6 +630,7 @@ pub enum Op { }, /// Stop the active root turn without recording a terminal turn event. + #[debug("SuspendTurnAndShutdown")] SuspendTurnAndShutdown { reply: oneshot::Sender>, }, @@ -620,6 +639,7 @@ pub enum Op { /// /// This uses the same submission queue as turn starts so app-server can /// preserve caller order between both kinds of mutation. + #[debug("ThreadSettings {{ requested_settings: {thread_settings:?} }}")] ThreadSettings { /// Sparse thread-settings overrides to apply. thread_settings: ThreadSettingsOverrides, @@ -630,6 +650,7 @@ pub enum Op { /// Update only the named running turn, without changing future settings. /// The reply reports the actual publication or why it did not occur. + #[debug("TurnSettings {{ turn_id: {turn_id:?}, requested_approvals_reviewer: {:?} }}", update.approvals_reviewer)] TurnSettings { turn_id: String, update: TurnSettingsUpdate, @@ -638,12 +659,14 @@ pub enum Op { /// Inter-agent communication that should be recorded as agent-message history /// while still using the normal thread submission lifecycle. + #[debug("InterAgentCommunication {{ id: {:?}, author: {:?}, recipient: {:?}, trigger_turn: {} }}", communication.id, communication.author, communication.recipient, communication.trigger_turn)] InterAgentCommunication { communication: InterAgentCommunication, start_options: TurnStartOptions, }, /// Approve a command execution + #[debug("ExecApproval {{ id: {id:?}, turn_id: {turn_id:?}, decision: {} }}", decision.to_opaque_string())] ExecApproval { /// The id of the submission we are approving id: String, @@ -654,6 +677,7 @@ pub enum Op { }, /// Approve a code patch + #[debug("PatchApproval {{ id: {id:?}, decision: {} }}", decision.to_opaque_string())] PatchApproval { /// The id of the submission we are approving id: String, @@ -662,6 +686,7 @@ pub enum Op { }, /// Resolve an MCP elicitation request. + #[debug("ResolveElicitation {{ request_id: {request_id:?}, decision: {decision:?} }}")] ResolveElicitation { /// Name of the MCP server that issued the request. server_name: String, @@ -676,6 +701,7 @@ pub enum Op { }, /// Resolve a request_user_input tool call. + #[debug("UserInputAnswer {{ id: {id:?} }}")] UserInputAnswer { /// Turn id for the in-flight request. id: String, @@ -684,6 +710,7 @@ pub enum Op { }, /// Resolve a request_permissions tool call. + #[debug("RequestPermissionsResponse {{ id: {id:?}, scope: {:?}, strict_auto_review: {} }}", response.scope, response.strict_auto_review)] RequestPermissionsResponse { /// Call id for the in-flight request. id: String, @@ -692,6 +719,7 @@ pub enum Op { }, /// Resolve a dynamic tool call request. + #[debug("DynamicToolResponse {{ id: {id:?}, success: {} }}", response.success)] DynamicToolResponse { /// Call id for the in-flight request. id: String, @@ -717,12 +745,24 @@ pub enum Op { /// /// This persists thread-level memory mode metadata without involving the /// model. + #[debug("SetThreadMemoryMode {{ mode: {mode:?} }}")] SetThreadMemoryMode { mode: ThreadMemoryMode }, /// Request a code review from the agent. + #[debug( + "Review {{ target: {} }}", + match &review_request.target { + ReviewTarget::UncommittedChanges => "uncommitted_changes", + ReviewTarget::BaseBranch { .. } => "base_branch", + ReviewTarget::Commit { .. } => "commit", + ReviewTarget::Custom { .. } => "custom", + }, + )] Review { review_request: ReviewRequest }, /// Record that the user approved one retry of a concrete Guardian-denied action. + // Assessment events are transient; retain the review identity when approving a retry. + #[debug("ApproveGuardianDeniedAction {{ review_id: {:?}, target_item_id: {:?}, turn_id: {:?}, status: {:?} }}", event.id, event.target_item_id, event.turn_id, event.status)] ApproveGuardianDeniedAction { event: GuardianAssessmentEvent }, /// Request to shut down codex instance. @@ -733,6 +773,7 @@ pub enum Op { /// The command string is executed using the user's default shell and may /// include shell syntax (pipes, redirects, etc.). Output is streamed via /// `ExecCommand*` events and the UI regains control upon `TurnComplete`. + #[debug("RunUserShellCommand {{ timeout_ms: {timeout_ms:?} }}")] RunUserShellCommand { /// The raw command string after '!' command: String,