diff --git a/Cargo.lock b/Cargo.lock index f2dafc6e2..1ed2ac773 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1643,6 +1643,7 @@ name = "nemo-relay-adaptive" version = "0.6.0" dependencies = [ "chrono", + "log", "nemo-relay", "redis", "regex", @@ -1679,6 +1680,7 @@ dependencies = [ "hyper-util", "jsonschema", "libc", + "log", "nemo-relay", "nemo-relay-adaptive", "nemo-relay-pii-redaction", @@ -1754,6 +1756,7 @@ name = "nemo-relay-pii-redaction" version = "0.6.0" dependencies = [ "futures", + "log", "nemo-relay", "opentelemetry_sdk", "regex", diff --git a/crates/adaptive/Cargo.toml b/crates/adaptive/Cargo.toml index a44349dc6..315c3c5c7 100644 --- a/crates/adaptive/Cargo.toml +++ b/crates/adaptive/Cargo.toml @@ -15,6 +15,7 @@ workspace = true [dependencies] nemo-relay.workspace = true +log = { version = "0.4", features = ["kv"] } uuid = { workspace = true, features = ["v4", "v7", "serde"] } serde = { version = "1", features = ["derive"] } serde_json = "1" diff --git a/crates/adaptive/src/drain.rs b/crates/adaptive/src/drain.rs index 3ffffb72c..02c813398 100644 --- a/crates/adaptive/src/drain.rs +++ b/crates/adaptive/src/drain.rs @@ -179,8 +179,12 @@ async fn store_run( backend: &Arc, completed_run: &RunRecord, ) -> bool { - if let Err(error) = backend.store_run_dyn(completed_run).await { - eprintln!("nemo-relay-adaptive drain: store_run failed: {error}"); + if backend.store_run_dyn(completed_run).await.is_err() { + log::warn!( + target: "nemo_relay.runtime", + event = "adaptive_run_storage_failed"; + "Adaptive runtime could not persist a completed run" + ); return false; } true @@ -193,11 +197,16 @@ async fn run_learners( hot_cache: &Arc>, ) { for learner in learners { - if let Err(error) = learner + if learner .process_run(completed_run, backend.as_ref(), hot_cache) .await + .is_err() { - eprintln!("nemo-relay-adaptive drain: learner failed: {error}"); + log::warn!( + target: "nemo_relay.runtime", + event = "adaptive_learner_failed"; + "Adaptive runtime learner failed while processing a completed run" + ); } } } @@ -213,7 +222,11 @@ async fn refresh_hot_cache_plan( guard.plan = plan; } } - Err(error) => eprintln!("nemo-relay-adaptive drain: load_plan failed: {error}"), + Err(_) => log::warn!( + target: "nemo_relay.runtime", + event = "adaptive_plan_refresh_failed"; + "Adaptive runtime could not refresh the cached plan" + ), } } diff --git a/crates/adaptive/src/redis.rs b/crates/adaptive/src/redis.rs index 923632d8f..76d4f4c82 100644 --- a/crates/adaptive/src/redis.rs +++ b/crates/adaptive/src/redis.rs @@ -55,12 +55,46 @@ impl RedisBackend { /// Returns [`AdaptiveError::Storage`] if the client cannot be created or the /// connection cannot be established. pub async fn new(url: &str, key_prefix: impl Into) -> Result { - let client = redis::Client::open(url) - .map_err(|e| AdaptiveError::Storage(format!("redis client: {e}")))?; - let conn = client - .get_connection_manager() - .await - .map_err(|e| AdaptiveError::Storage(format!("redis connection: {e}")))?; + log::info!( + target: "nemo_relay.plugin", + event = "plugin_resource_access_pending", + plugin_kind = "adaptive", + resource_kind = "redis", + permission = "connect"; + "Plugin Redis connectivity validation started" + ); + let client = redis::Client::open(url).map_err(|e| { + log::warn!( + target: "nemo_relay.plugin", + event = "plugin_resource_access_failed", + plugin_kind = "adaptive", + resource_kind = "redis", + permission = "connect", + reason = "client_configuration"; + "Plugin resource access validation failed" + ); + AdaptiveError::Storage(format!("redis client: {e}")) + })?; + let conn = client.get_connection_manager().await.map_err(|e| { + log::warn!( + target: "nemo_relay.plugin", + event = "plugin_resource_access_failed", + plugin_kind = "adaptive", + resource_kind = "redis", + permission = "connect", + reason = "connection_failed"; + "Plugin resource access validation failed" + ); + AdaptiveError::Storage(format!("redis connection: {e}")) + })?; + log::info!( + target: "nemo_relay.plugin", + event = "plugin_resource_connected", + plugin_kind = "adaptive", + resource_kind = "redis", + permission = "connect"; + "Plugin Redis connectivity established" + ); Ok(Self { client, conn, diff --git a/crates/adaptive/src/runtime/backend.rs b/crates/adaptive/src/runtime/backend.rs index dedc4bcc4..dd5c200f6 100644 --- a/crates/adaptive/src/runtime/backend.rs +++ b/crates/adaptive/src/runtime/backend.rs @@ -14,7 +14,16 @@ pub async fn build_backend( backend: &BackendSpec, ) -> Result> { match backend.kind.as_str() { - "in_memory" => Ok(Arc::new(InMemoryBackend::new())), + "in_memory" => { + log::info!( + target: "nemo_relay.plugin", + event = "plugin_resource_validation_completed", + plugin_kind = "adaptive", + resource_count = 0; + "Plugin resource validation completed" + ); + Ok(Arc::new(InMemoryBackend::new())) + } #[cfg(feature = "redis-backend")] "redis" => { let url = backend diff --git a/crates/adaptive/src/runtime/features.rs b/crates/adaptive/src/runtime/features.rs index af2553a9e..79cbbad61 100644 --- a/crates/adaptive/src/runtime/features.rs +++ b/crates/adaptive/src/runtime/features.rs @@ -392,10 +392,14 @@ impl AdaptiveRuntime { if self.config.acg.is_some() && let Some(backend) = self.backend.as_ref() - && let Err(error) = + && let Err(_) = load_persisted_acg_state(&agent_id, backend.as_ref(), &self.hot_cache).await { - eprintln!("nemo-relay-adaptive: acg hot cache seeding failed: {error}"); + log::warn!( + target: "nemo_relay.runtime", + event = "adaptive_acg_cache_seed_failed"; + "Adaptive runtime could not seed the ACG hot cache" + ); } let mut pending = self.pending_features(&agent_id); @@ -431,7 +435,11 @@ impl AdaptiveRuntime { guard.plan = plan; } } - Err(error) => eprintln!("nemo-relay-adaptive: hot cache seeding failed: {error}"), + Err(_) => log::warn!( + target: "nemo_relay.runtime", + event = "adaptive_hot_cache_seed_failed"; + "Adaptive runtime could not seed the hot cache" + ), } } diff --git a/crates/adaptive/tests/integration/redis_tests.rs b/crates/adaptive/tests/integration/redis_tests.rs index 34dcadb5a..9cd730ae6 100644 --- a/crates/adaptive/tests/integration/redis_tests.rs +++ b/crates/adaptive/tests/integration/redis_tests.rs @@ -8,7 +8,7 @@ #![cfg(feature = "redis-backend")] -use std::sync::{Arc, RwLock}; +use std::sync::{Arc, Once, RwLock}; use chrono::Utc; use nemo_relay::codec::request::{AnnotatedLlmRequest, Message, MessageContent}; @@ -29,6 +29,7 @@ use nemo_relay_adaptive::types::plan::ExecutionPlan; use nemo_relay_adaptive::types::records::{CallKind, CallRecord, RunRecord}; const REDIS_TEST_ENV: &str = "NEMO_RELAY_RUN_REDIS_TESTS"; +static TEST_LOGGING: Once = Once::new(); // --------------------------------------------------------------------------- // Helpers @@ -41,9 +42,19 @@ fn env_value_is_truthy(value: Option<&str>) -> bool { ) } +fn enable_operational_logs() { + TEST_LOGGING.call_once(|| { + let runtime = + nemo_relay::logging::init_logging(&nemo_relay::logging::LoggingConfig::default()) + .expect("test logging should initialize"); + Box::leak(Box::new(runtime)); + }); +} + /// Attempt to connect to a local Redis instance. Returns `None` (skip) if /// Redis tests were not explicitly enabled or Redis is unavailable. async fn get_test_redis() -> Option { + enable_operational_logs(); let redis_test_env = std::env::var_os(REDIS_TEST_ENV).map(|value| value.to_string_lossy().into_owned()); if !env_value_is_truthy(redis_test_env.as_deref()) { @@ -65,6 +76,7 @@ async fn get_test_redis() -> Option { } async fn get_test_redis_with_prefix() -> Option<(RedisBackend, String)> { + enable_operational_logs(); let prefix = format!("test:{}:", Uuid::now_v7()); match RedisBackend::new("redis://127.0.0.1/", prefix.clone()).await { Ok(backend) => Some((backend, prefix)), diff --git a/crates/adaptive/tests/integration/runtime_integration_tests.rs b/crates/adaptive/tests/integration/runtime_integration_tests.rs index d02f4f4d4..5b68723a2 100644 --- a/crates/adaptive/tests/integration/runtime_integration_tests.rs +++ b/crates/adaptive/tests/integration/runtime_integration_tests.rs @@ -4,7 +4,7 @@ //! Integration tests for runtime integration in the NeMo Relay adaptive crate. use std::pin::Pin; -use std::sync::{Arc, Mutex as StdMutex, RwLock}; +use std::sync::{Arc, Mutex as StdMutex, Once, RwLock}; use chrono::Utc; use nemo_relay::api::event::Event; @@ -48,12 +48,23 @@ use tokio_stream::StreamExt; use uuid::Uuid; static TEST_MUTEX: Mutex<()> = Mutex::const_new(()); +static TEST_LOGGING: Once = Once::new(); + +fn enable_operational_logs() { + TEST_LOGGING.call_once(|| { + let runtime = + nemo_relay::logging::init_logging(&nemo_relay::logging::LoggingConfig::default()) + .expect("test logging should initialize"); + Box::leak(Box::new(runtime)); + }); +} fn short_hash(value: &str) -> &str { value.get(..16).unwrap_or(value) } fn reset_global() { + enable_operational_logs(); let _ = clear_plugin_configuration(); let _ = deregister_plugin("test.header_plugin"); let _ = deregister_plugin("test.failing_plugin"); diff --git a/crates/cli/Cargo.toml b/crates/cli/Cargo.toml index 6115664d9..c80ff9b07 100644 --- a/crates/cli/Cargo.toml +++ b/crates/cli/Cargo.toml @@ -46,6 +46,7 @@ hyper = "1" hyper-util = { version = "0.1", features = ["tokio"] } dialoguer = { version = "0.11", default-features = false, features = ["password"] } jsonschema = { version = "0.46.6", default-features = false } +log = { version = "0.4", features = ["kv"] } percent-encoding = "2" reqwest = { version = "0.12", default-features = false, features = ["charset", "http2", "json", "rustls-tls-native-roots", "stream"] } regex = "1" diff --git a/crates/cli/src/bootstrap/mod.rs b/crates/cli/src/bootstrap/mod.rs index 54c890e00..fbd9142d4 100644 --- a/crates/cli/src/bootstrap/mod.rs +++ b/crates/cli/src/bootstrap/mod.rs @@ -91,11 +91,48 @@ impl GatewaySpec { /// Return the compatible gateway already bound at this endpoint, or start the existing server /// under a per-user lock and wait for authenticated readiness. pub(crate) fn acquire(&self) -> Result { - acquire_gateway(self) + match acquire_gateway(self) { + Ok(endpoint) => Ok(endpoint), + Err(error) => { + log::error!( + target: "nemo_relay.bootstrap", + event = "gateway_acquisition_failed", + bind = self.bind.to_string().as_str(); + "Gateway acquisition failed" + ); + Err(error) + } + } } pub(crate) fn recover(&self, expected_instance: &str) -> Result { - recover_gateway(self, expected_instance) + log::warn!( + target: "nemo_relay.bootstrap", + event = "gateway_recovery_started", + instance_id = expected_instance; + "Gateway recovery started" + ); + match recover_gateway(self, expected_instance) { + Ok(endpoint) => { + log::info!( + target: "nemo_relay.bootstrap", + event = "gateway_recovered", + previous_instance_id = expected_instance, + instance_id = endpoint.instance_id.as_str(); + "Gateway recovery completed" + ); + Ok(endpoint) + } + Err(error) => { + log::error!( + target: "nemo_relay.bootstrap", + event = "gateway_recovery_failed", + instance_id = expected_instance; + "Gateway recovery failed" + ); + Err(error) + } + } } pub(crate) fn healthy_instance(&self, url: &str) -> Option { @@ -235,6 +272,13 @@ fn compatible_endpoint( instance_id: Option, ) -> Result { let instance_id = instance_id.ok_or_else(|| foreign_listener_error(&url))?; + log::info!( + target: "nemo_relay.bootstrap", + event = "gateway_reused", + instance_id = instance_id.as_str(), + address = address.to_string().as_str(); + "An existing gateway was reused" + ); Ok(GatewayEndpoint { address, url, @@ -255,6 +299,12 @@ fn incompatible_relay_error(url: &str) -> String { } fn start_gateway(spec: &GatewaySpec, state: &Path) -> Result { + log::info!( + target: "nemo_relay.bootstrap", + event = "gateway_spawn_started", + bind = spec.bind.to_string().as_str(); + "Gateway process spawn started" + ); let relay = relay_binary()?; let ready_path = state.join(format!( "gateway-{}-{}.ready.json", @@ -302,7 +352,14 @@ fn start_gateway(spec: &GatewaySpec, state: &Path) -> Result Result( } return Err(format!("failed to start gateway reaper thread: {error}")); } + log::info!( + target: "nemo_relay.bootstrap", + event = "gateway_reaper_handoff"; + "Gateway process ownership was handed to the reaper" + ); Ok(()) } diff --git a/crates/cli/src/commands/mod.rs b/crates/cli/src/commands/mod.rs index 2e96e3166..4a2879b69 100644 --- a/crates/cli/src/commands/mod.rs +++ b/crates/cli/src/commands/mod.rs @@ -55,6 +55,11 @@ pub(crate) async fn run(bootstrap_shutdown_token: Option) -> ExitCode { // top-level server flags so transparent launch can share config parsing with daemon startup. async fn dispatch(bootstrap_shutdown_token: Option) -> Result { let cli = Cli::parse(); + let command_name = cli + .command + .as_ref() + .map(Command::log_name) + .unwrap_or("default"); let initialize_logging = match cli.command.as_ref() { Some(command) => !command.skips_logging(), @@ -82,10 +87,48 @@ async fn dispatch(bootstrap_shutdown_token: Option) -> Result run_command(command, &cli.server).await, None => run_default(&cli.server, bootstrap_shutdown_token).await, + }; + match &result { + Ok(code) if *code == ExitCode::SUCCESS => log::info!( + target: "nemo_relay.cli", + event = "command_completed", + command = command_name, + outcome = "success"; + "CLI command completed" + ), + Ok(_) => log::warn!( + target: "nemo_relay.cli", + event = "command_completed", + command = command_name, + outcome = "nonzero_exit"; + "CLI command completed with a non-zero exit status" + ), + Err(error) if error.guardrail_rejection_reason().is_some() => log::warn!( + target: "nemo_relay.cli", + event = "command_rejected", + command = command_name, + error_kind = error.log_kind(); + "CLI command was rejected by policy" + ), + Err(error) => log::error!( + target: "nemo_relay.cli", + event = "command_failed", + command = command_name, + error_kind = error.log_kind(); + "CLI command failed" + ), } + result } async fn run_command(command: Command, server: &ServerArgs) -> Result { diff --git a/crates/cli/src/commands/root.rs b/crates/cli/src/commands/root.rs index df3ab0b0e..9cce1033a 100644 --- a/crates/cli/src/commands/root.rs +++ b/crates/cli/src/commands/root.rs @@ -126,10 +126,38 @@ pub(crate) enum Command { } impl Command { + pub(crate) fn log_name(&self) -> &'static str { + match self { + Self::Claude(_) => "claude", + Self::Codex(_) => "codex", + Self::Hermes(_) => "hermes", + Self::Mcp => "mcp", + Self::Config(_) => "config", + Self::Plugins(_) => "plugins", + Self::Install(_) => "install", + Self::Uninstall(_) => "uninstall", + Self::ModelPricing(_) => "model_pricing", + Self::Doctor(_) => "doctor", + Self::Agents(_) => "agents", + Self::Completions(_) => "completions", + Self::Run(_) => "run", + Self::HookForward(_) => "hook_forward", + } + } + /// Configuration-editing commands remain available even when operational logging settings are /// invalid, so users can repair their configuration. pub(crate) fn skips_logging(&self) -> bool { matches!(self, Self::Config(_)) || matches!(self, Self::Plugins(command) if command.is_edit()) + || matches!(self, Self::HookForward(command) if transparent_hook_is_inert(command)) } } + +fn transparent_hook_is_inert(command: &HookForwardCommand) -> bool { + !command.transparent_run + && std::env::var(crate::configuration::TRANSPARENT_RUN_ENV) + .ok() + .as_deref() + == Some("1") +} diff --git a/crates/cli/src/configuration/mod.rs b/crates/cli/src/configuration/mod.rs index 47239d0bc..e8c2bf5ff 100644 --- a/crates/cli/src/configuration/mod.rs +++ b/crates/cli/src/configuration/mod.rs @@ -94,6 +94,13 @@ pub(crate) fn resolve_server_config(args: &GatewayOverrides) -> Result, ) -> Result { - load_shared_config(explicit, None) + let resolved = load_shared_config(explicit, None)?; + log::info!( + target: "nemo_relay.configuration", + event = "plugin_configuration_resolved", + dynamic_plugin_count = resolved.dynamic_plugins.len(); + "Plugin configuration resolved" + ); + Ok(resolved) } /// Resolves transparent `run` configuration and switches the gateway to an ephemeral bind address. @@ -883,6 +897,13 @@ pub(crate) fn resolve_run_config( if !command.dry_run { enforce_required_dynamic_plugin_startup(config, &resolved)?; } + log::info!( + target: "nemo_relay.configuration", + event = "configuration_resolved", + mode = "run", + dynamic_plugin_count = resolved.dynamic_plugins.len(); + "Runtime configuration resolved" + ); Ok(resolved) } diff --git a/crates/cli/src/diagnostics/mod.rs b/crates/cli/src/diagnostics/mod.rs index 15d485d51..0a3e1560d 100644 --- a/crates/cli/src/diagnostics/mod.rs +++ b/crates/cli/src/diagnostics/mod.rs @@ -64,21 +64,39 @@ pub(crate) async fn collect_report( details: "valid".into(), }, ), - Err(err) => ( - ResolvedConfig::default(), - Check { - name: "Resolution", - status: Status::Fail, - details: format!("could not resolve merged config: {err}"), - }, - ), + Err(err) => { + log::warn!( + target: "nemo_relay.diagnostics", + event = "diagnostic_probe_failed", + probe = "configuration", + error_kind = err.log_kind(); + "Diagnostic probe failed" + ); + ( + ResolvedConfig::default(), + Check { + name: "Resolution", + status: Status::Fail, + details: format!("could not resolve merged config: {err}"), + }, + ) + } }; let cwd = std::env::current_dir().ok(); let home = home_dir(); let configured_agents = configured_agent_names(&resolved.agents); let (plugin_sources, plugin_error) = match effective_plugin_toml_sources() { Ok(sources) => (sources, None), - Err(error) => (Vec::new(), Some(error.to_string())), + Err(error) => { + log::warn!( + target: "nemo_relay.diagnostics", + event = "diagnostic_probe_failed", + probe = "plugin_configuration", + error_kind = error.log_kind(); + "Diagnostic probe failed" + ); + (Vec::new(), Some(error.to_string())) + } }; let plugin_resolution = plugin_resolution_check(&resolved, &resolution, plugin_error.as_deref()); @@ -1167,6 +1185,15 @@ pub(crate) async fn run_doctor( json: bool, ) -> Result { let report = collect_report(target_agent).await?; + log::info!( + target: "nemo_relay.diagnostics", + event = "diagnostics_completed", + agent_count = report.agents.len(), + host_plugin_count = report.host_plugins.len(), + observability_check_count = report.observability.len(), + completion_check_count = report.completions.len(); + "Diagnostics completed" + ); if json { print!("{}", format_json(&report)?); } else { @@ -1185,6 +1212,13 @@ pub(crate) async fn run_doctor( /// decisions (e.g., CI gating on JSON output). pub(crate) async fn run_agents(json: bool) -> Result { let agents = agents_report().await?; + log::info!( + target: "nemo_relay.diagnostics", + event = "diagnostics_completed", + agent_count = agents.len(), + report = "agents"; + "Agent diagnostics completed" + ); let output = if json { format_agents_json(&agents)? } else { diff --git a/crates/cli/src/error.rs b/crates/cli/src/error.rs index 41865a537..4e6e50e4a 100644 --- a/crates/cli/src/error.rs +++ b/crates/cli/src/error.rs @@ -50,6 +50,11 @@ pub(crate) enum CliError { Config(String), #[error("launcher error: {0}")] Launch(String), + #[error("nemo-relay hook forward failed: {source}")] + HookDelivery { + #[source] + source: Box, + }, #[error("{message}")] PluginLifecycle { command: &'static str, @@ -65,10 +70,32 @@ pub(crate) enum CliError { } impl CliError { + pub(crate) fn log_kind(&self) -> &'static str { + match self { + Self::GuardrailRejected(_) => "guardrail_rejected", + Self::InvalidPayload(_) => "invalid_payload", + Self::PayloadTooLarge(_) => "payload_too_large", + Self::Unauthorized(_) => "unauthorized", + Self::Upstream(_) => "upstream", + Self::ProviderFailure(_) => "provider_failure", + Self::Http(_) => "http", + Self::Io(_) => "io", + Self::Install(_) => "install", + Self::Config(_) => "configuration", + Self::Launch(_) => "launch", + Self::HookDelivery { source } => source.log_kind(), + Self::PluginLifecycle { .. } => "plugin_lifecycle", + Self::Flow(FlowError::GuardrailRejected(_)) => "guardrail_rejected", + Self::Flow(_) => "runtime", + Self::OpenInference(_) => "openinference", + } + } + pub(crate) fn guardrail_rejection_reason(&self) -> Option<&str> { match self { Self::GuardrailRejected(reason) => Some(reason), Self::Flow(FlowError::GuardrailRejected(reason)) => Some(reason), + Self::HookDelivery { source } => source.guardrail_rejection_reason(), _ => None, } } @@ -137,3 +164,7 @@ impl IntoResponse for CliError { (status, body).into_response() } } + +#[cfg(test)] +#[path = "../tests/coverage/shared/error_tests.rs"] +mod tests; diff --git a/crates/cli/src/gateway/mod.rs b/crates/cli/src/gateway/mod.rs index c1f2f25dd..edbbf1cee 100644 --- a/crates/cli/src/gateway/mod.rs +++ b/crates/cli/src/gateway/mod.rs @@ -100,9 +100,14 @@ async fn run_managed_gateway( let session_id = prep.session_id.clone(); let session_finish = prep.session_finish; let model = prep.model_name.as_deref().unwrap_or(""); - eprintln!( - "nemo-relay CLI gateway: bypassing managed LLM observability for Claude Code startup probe session={session_id} provider={} model={model}", - prep.provider_name + log::warn!( + target: "nemo_relay.gateway", + event = "observability_bypassed", + session_id = session_id.as_str(), + provider = prep.provider_name.as_str(), + model = model, + reason = "startup_probe"; + "Managed observability was bypassed for a startup probe" ); state .sessions @@ -796,9 +801,12 @@ fn effective_dispatch_request( body_reencoded = true; Bytes::from(serialized) } - Err(error) => { - eprintln!( - "nemo-relay CLI gateway: failed to serialize rewritten LLM request body; forwarding original request: {error}" + Err(_) => { + log::warn!( + target: "nemo_relay.gateway", + event = "request_rewrite_fallback", + reason = "serialization_failed"; + "The original upstream request was retained after rewrite serialization failed" ); return EffectiveUpstreamRequest { body_bytes: body_bytes.clone(), diff --git a/crates/cli/src/hooks/delivery.rs b/crates/cli/src/hooks/delivery.rs index 17bb60fff..b8db65620 100644 --- a/crates/cli/src/hooks/delivery.rs +++ b/crates/cli/src/hooks/delivery.rs @@ -132,8 +132,26 @@ fn capture_generation_guard( } fn handle_hook_error(error: CliError, fail_closed: bool) -> Result<(), CliError> { - eprintln!("nemo-relay hook forward failed: {error}"); - if fail_closed { Err(error) } else { Ok(()) } + if fail_closed { + log::error!( + target: "nemo_relay.hook", + event = "hook_delivery_failed", + mode = "fail_closed", + error_kind = error.log_kind(); + "Hook delivery failed" + ); + Err(error) + } else { + log::warn!( + target: "nemo_relay.hook", + event = "hook_delivery_failed", + mode = "fail_open", + error_kind = error.log_kind(); + "Hook delivery failed open" + ); + eprintln!("nemo-relay hook forward failed: {error}"); + Ok(()) + } } // Reads the native hook payload from stdin and normalizes empty payloads to JSON object syntax. diff --git a/crates/cli/src/hooks/response.rs b/crates/cli/src/hooks/response.rs index c06264fba..0db107ea1 100644 --- a/crates/cli/src/hooks/response.rs +++ b/crates/cli/src/hooks/response.rs @@ -19,21 +19,14 @@ pub(super) async fn handle_hook_forward_response( let status = response.status(); let body = match read_hook_response(response).await { Ok(body) => body, - Err(error) if fail_closed => return Err(error), Err(error) => { - eprintln!("nemo-relay hook forward failed: {error}"); - return Ok(()); + return handle_hook_failure(error, fail_closed, "response_read", None); } }; handle_hook_forward_status(status, body, fail_closed) } Err(error) => { - eprintln!("nemo-relay hook forward failed: {error}"); - if fail_closed { - Err(CliError::Upstream(error)) - } else { - Ok(()) - } + handle_hook_failure(CliError::Upstream(error), fail_closed, "transport", None) } } } @@ -51,12 +44,12 @@ pub(crate) fn handle_verified_hook_forward_response( Ok(status) => status, Err(error) => { let message = format!("verified hook response had an invalid status: {error}"); - eprintln!("nemo-relay hook forward failed: {message}"); - return if fail_closed { - Err(CliError::Install(message)) - } else { - Ok(()) - }; + return handle_hook_failure( + CliError::Install(message), + fail_closed, + "invalid_status", + None, + ); } }; handle_hook_forward_status( @@ -65,16 +58,12 @@ pub(crate) fn handle_verified_hook_forward_response( fail_closed, ) } - Err(error) => { - eprintln!("nemo-relay hook forward failed: {error}"); - if fail_closed { - Err(CliError::Install(format!( - "verified hook forward failed: {error}" - ))) - } else { - Ok(()) - } - } + Err(error) => handle_hook_failure( + CliError::Install(format!("verified hook forward failed: {error}")), + fail_closed, + "verified_transport", + None, + ), } } @@ -87,13 +76,12 @@ pub(crate) fn handle_hook_forward_status( if let Some(reason) = guardrail_rejection_reason(&body) { return Err(CliError::GuardrailRejected(reason)); } - eprintln!("nemo-relay hook forward failed with HTTP {status}"); - if fail_closed { - return Err(CliError::Install(format!( - "hook forward failed with HTTP {status}" - ))); - } - return Ok(()); + return handle_hook_failure( + CliError::Install(format!("hook forward failed with HTTP {status}")), + fail_closed, + "http_status", + Some(status.as_u16()), + ); } if !body.is_empty() { println!("{body}"); @@ -101,6 +89,45 @@ pub(crate) fn handle_hook_forward_status( Ok(()) } +fn handle_hook_failure( + error: CliError, + fail_closed: bool, + reason: &'static str, + status_code: Option, +) -> Result<(), CliError> { + let mode = if fail_closed { + "fail_closed" + } else { + "fail_open" + }; + if fail_closed { + log::error!( + target: "nemo_relay.hook", + event = "hook_delivery_failed", + mode, + reason, + status_code, + error_kind = error.log_kind(); + "Hook delivery failed" + ); + Err(CliError::HookDelivery { + source: Box::new(error), + }) + } else { + log::warn!( + target: "nemo_relay.hook", + event = "hook_delivery_failed", + mode, + reason, + status_code, + error_kind = error.log_kind(); + "Hook delivery failed open" + ); + eprintln!("nemo-relay hook forward failed: {error}"); + Ok(()) + } +} + pub(super) async fn read_hook_response(response: reqwest::Response) -> Result { let mut stream = response.bytes_stream(); let mut body = Vec::new(); diff --git a/crates/cli/src/installation/marketplace/mod.rs b/crates/cli/src/installation/marketplace/mod.rs index a65958b6e..c00c5e65f 100644 --- a/crates/cli/src/installation/marketplace/mod.rs +++ b/crates/cli/src/installation/marketplace/mod.rs @@ -141,6 +141,14 @@ pub(crate) fn install( host: impl MarketplaceHost, command: InstallRequest, ) -> Result { + let host_name = host.install_arg(); + log::info!( + target: "nemo_relay.installation", + event = "installation_started", + host = host_name, + dry_run = command.dry_run; + "Plugin installation started" + ); let operation_lock_dir = if command.dry_run { PathBuf::new() } else { @@ -156,13 +164,37 @@ pub(crate) fn install( dry_run: command.dry_run, skip_doctor: command.skip_doctor, }; - run_for_host(host, &options, install_host) + let result = run_for_host(host, &options, install_host); + match &result { + Ok(_) => log::info!( + target: "nemo_relay.installation", + event = "installation_completed", + host = host_name; + "Plugin installation completed" + ), + Err(error) => log::error!( + target: "nemo_relay.installation", + event = "installation_failed", + host = host_name, + error_kind = error.log_kind(); + "Plugin installation failed" + ), + } + result } pub(crate) fn uninstall( host: impl MarketplaceHost, command: UninstallRequest, ) -> Result { + let host_name = host.install_arg(); + log::info!( + target: "nemo_relay.installation", + event = "uninstallation_started", + host = host_name, + dry_run = command.dry_run; + "Plugin uninstallation started" + ); let operation_lock_dir = if command.dry_run { PathBuf::new() } else { @@ -178,7 +210,23 @@ pub(crate) fn uninstall( dry_run: command.dry_run, skip_doctor: true, }; - run_for_host(host, &options, uninstall_host) + let result = run_for_host(host, &options, uninstall_host); + match &result { + Ok(_) => log::info!( + target: "nemo_relay.installation", + event = "uninstallation_completed", + host = host_name; + "Plugin uninstallation completed" + ), + Err(error) => log::error!( + target: "nemo_relay.installation", + event = "uninstallation_failed", + host = host_name, + error_kind = error.log_kind(); + "Plugin uninstallation failed" + ), + } + result } pub(crate) fn plugin_doctor_options(install_dir: Option) -> PluginInstallOptions { @@ -1039,10 +1087,16 @@ fn uninstall_host_with_setup_override( plugin_setup_installed: true, }); layout.validate_persisted_state(&state)?; - if let Err(error) = require_relay(options, runner) + if let Err(_error) = require_relay(options, runner) .and_then(|relay| validate_relay_hook_forward(&relay, options, runner)) { - eprintln!("warning: skipping nemo-relay validation during uninstall: {error}"); + log::warn!( + target: "nemo_relay.installation", + event = "installation_validation_skipped", + operation = "uninstall", + error_kind = "validation"; + "Relay validation was skipped during uninstall" + ); } let mut state = state; if force_plugin_setup_uninstall && !state.plugin_setup_installed { @@ -1530,19 +1584,31 @@ impl Drop for ReplacementGenerationLock { match fs::metadata(retirement.marker_path()) { Err(error) if error.kind() == std::io::ErrorKind::NotFound => true, Err(error) => { - eprintln!( - "warning: retaining MCP generation lock {} because marker {} could not be inspected: {error}", - self.lock_path.display(), - retirement.marker_path().display() + let lock_path = self.lock_path.display().to_string(); + let marker_path = retirement.marker_path().display().to_string(); + let error_kind = error.kind().to_string(); + log::warn!( + target: "nemo_relay.installation", + event = "installation_cleanup_deferred", + component = "mcp_generation_lock", + path = lock_path.as_str(), + marker_path = marker_path.as_str(), + error_kind = error_kind.as_str(); + "An MCP generation lock was retained because its marker could not be inspected" ); false } Ok(_) => match retirement.visible_marker_uses_transaction_lock() { Ok(referenced) => !referenced, - Err(error) => { - eprintln!( - "warning: retaining MCP generation lock {} because its marker reference could not be verified: {error}", - self.lock_path.display() + Err(_error) => { + let lock_path = self.lock_path.display().to_string(); + log::warn!( + target: "nemo_relay.installation", + event = "installation_cleanup_deferred", + component = "mcp_generation_lock", + path = lock_path.as_str(), + error_kind = "marker_reference"; + "An MCP generation lock was retained because its marker reference could not be verified" ); false } @@ -1708,9 +1774,10 @@ impl ForceInstallSnapshot { match fs::remove_dir_all(&self.backup_marketplace_root) { Ok(()) => {} Err(error) if error.kind() == std::io::ErrorKind::NotFound => {} - Err(error) => eprintln!( - "warning: failed to remove replaced marketplace backup {}: {error}", - self.backup_marketplace_root.display() + Err(error) => log_cleanup_failure( + "marketplace_backup", + &self.backup_marketplace_root, + error.kind(), ), } } @@ -1720,10 +1787,9 @@ impl ForceInstallSnapshot { match fs::remove_dir_all(backup_plugin_root) { Ok(()) => {} Err(error) if error.kind() == std::io::ErrorKind::NotFound => {} - Err(error) => eprintln!( - "warning: failed to remove replaced plugin backup {}: {error}", - backup_plugin_root.display() - ), + Err(error) => { + log_cleanup_failure("plugin_backup", backup_plugin_root, error.kind()) + } } } drop(self.generation_retirement.take()); @@ -1737,13 +1803,23 @@ fn remove_generation_lock_best_effort(path: &Path) { match fs::remove_file(path) { Ok(()) => {} Err(error) if error.kind() == std::io::ErrorKind::NotFound => {} - Err(error) => eprintln!( - "warning: failed to remove retired MCP generation lock {}: {error}", - path.display() - ), + Err(error) => log_cleanup_failure("mcp_generation_lock", path, error.kind()), } } +fn log_cleanup_failure(component: &'static str, path: &Path, error_kind: std::io::ErrorKind) { + let path = path.display().to_string(); + let error_kind = error_kind.to_string(); + log::warn!( + target: "nemo_relay.installation", + event = "installation_cleanup_failed", + component = component, + path = path.as_str(), + error_kind = error_kind.as_str(); + "Installation cleanup failed" + ); +} + fn generation_lock_is_absent(path: &Path) -> bool { matches!( fs::symlink_metadata(path), diff --git a/crates/cli/src/mcp/mod.rs b/crates/cli/src/mcp/mod.rs index 6eecd7060..558cbb3d3 100644 --- a/crates/cli/src/mcp/mod.rs +++ b/crates/cli/src/mcp/mod.rs @@ -22,6 +22,11 @@ pub(crate) const SERVER_NAME: &str = "nemo-relay"; const LAUNCH_ARGS: &[&str] = &["mcp"]; pub(crate) async fn run(server_args: &GatewayOverrides) -> Result { + log::info!( + target: "nemo_relay.mcp", + event = "mcp_session_started"; + "MCP session started" + ); if transparent_run_active() { // An installed plugin can still be enabled inside `nemo-relay run`. In that process the // wrapper already owns a healthy dynamic gateway, so this MCP instance authenticates and @@ -36,9 +41,32 @@ pub(crate) async fn run(server_args: &GatewayOverrides) -> Result { + log::info!( + target: "nemo_relay.mcp", + event = "mcp_session_closed"; + "MCP session closed" + ); + Ok(ExitCode::SUCCESS) + } + Err(error) => { + log::error!( + target: "nemo_relay.mcp", + event = "mcp_session_failed", + error_kind = error.log_kind(); + "MCP session failed" + ); + Err(error) + } + }; } // Starting the MCP process is the lifecycle boundary. Acquire the shared gateway before // reading protocol frames so hosts can rely on process startup rather than their individual @@ -47,9 +75,32 @@ pub(crate) async fn run(server_args: &GatewayOverrides) -> Result { + log::info!( + target: "nemo_relay.mcp", + event = "mcp_session_closed"; + "MCP session closed" + ); + Ok(ExitCode::SUCCESS) + } + Err(error) => { + log::error!( + target: "nemo_relay.mcp", + event = "mcp_session_failed", + error_kind = error.log_kind(); + "MCP session failed" + ); + Err(error) + } + } } /// Builds the host-independent persistent MCP launch contract. diff --git a/crates/cli/src/process/detached.rs b/crates/cli/src/process/detached.rs index c5b061fb3..957bf1989 100644 --- a/crates/cli/src/process/detached.rs +++ b/crates/cli/src/process/detached.rs @@ -358,8 +358,11 @@ pub(crate) fn configure_detached(_command: &mut Command) { let (in_job, limits) = current_windows_job_limits(); let (_, limited_lifetime) = windows_creation_flags(in_job, limits); if limited_lifetime { - eprintln!( - "warning: the current Windows Job Object does not permit process breakaway; the shared Relay gateway lifetime is limited to the host job" + log::warn!( + target: "nemo_relay.bootstrap", + event = "gateway_lifetime_limited", + reason = "windows_job_breakaway_denied"; + "The shared gateway lifetime is limited to the host job" ); } } @@ -382,9 +385,12 @@ pub(crate) fn terminate_tree(child: &mut DetachedChild) { .args(["/PID", &child.id().to_string(), "/T", "/F"]) .status(); if !status.is_ok_and(|status| status.success()) { - eprintln!( - "failed to terminate detached gateway process tree {} with taskkill", - child.id() + log::error!( + target: "nemo_relay.bootstrap", + event = "gateway_cleanup_failed", + process_id = child.id(), + reason = "taskkill_failed"; + "Detached gateway process cleanup failed" ); return; } diff --git a/crates/cli/src/process/launcher.rs b/crates/cli/src/process/launcher.rs index 62a8d70b0..4b8f497a7 100644 --- a/crates/cli/src/process/launcher.rs +++ b/crates/cli/src/process/launcher.rs @@ -112,16 +112,47 @@ impl TransparentRun { if self.dry_run { return Ok(ExitCode::SUCCESS); } + let agent = self.agent.as_arg(); + log::info!( + target: "nemo_relay.agent", + event = "agent_launch_started", + agent = agent; + "Agent launch started" + ); self.prepared .print_live_status(self.agent, &self.gateway_url, &self.resolved); - execute_live_run_with_dynamic( + let result = execute_live_run_with_dynamic( self.listener, self.resolved.gateway, self.dynamic_plugins, &self.gateway_url, self.prepared, ) - .await + .await; + match &result { + Ok(code) if *code == ExitCode::SUCCESS => log::info!( + target: "nemo_relay.agent", + event = "agent_exited", + agent = agent, + outcome = "success"; + "Agent exited" + ), + Ok(_) => log::warn!( + target: "nemo_relay.agent", + event = "agent_exited", + agent = agent, + outcome = "failure"; + "Agent exited unsuccessfully" + ), + Err(error) => log::error!( + target: "nemo_relay.agent", + event = "agent_run_failed", + agent = agent, + error_kind = error.log_kind(); + "Agent run failed" + ), + } + result } } diff --git a/crates/cli/src/server/mod.rs b/crates/cli/src/server/mod.rs index 2a3a36824..a263f0a54 100644 --- a/crates/cli/src/server/mod.rs +++ b/crates/cli/src/server/mod.rs @@ -91,6 +91,13 @@ pub(crate) async fn serve_with_dynamic( ready_file: Option<&Path>, bootstrap_shutdown_token: Option, ) -> Result<(), CliError> { + let bind = config.bind.to_string(); + log::info!( + target: "nemo_relay.server", + event = "server_starting", + bind = bind.as_str(); + "Gateway server is starting" + ); let listener = bind_listener(config.bind).await?; print_startup_status(listener.local_addr()?, &config); let bootstrap_fingerprint = managed_bootstrap @@ -304,6 +311,14 @@ async fn serve_listener_with_dynamic_inner( if let Some(path) = ready_file { write_ready_file(path, local_address, &instance_id)?; } + let address = local_address.to_string(); + log::info!( + target: "nemo_relay.server", + event = "server_listening", + address = address.as_str(), + instance_id = instance_id.as_str(); + "Gateway server is listening" + ); let idle_shutdown: Option = if matches!(&shutdown_mode, None | Some(ShutdownMode::ProcessSignal)) { plugin_idle_timeout()?.map(|timeout| { @@ -318,6 +333,12 @@ async fn serve_listener_with_dynamic_inner( }; let shutdown = server_shutdown_future(shutdown_mode, idle_shutdown); let shutdown = combine_shutdown_futures(shutdown, bootstrap_shutdown_rx); + log::info!( + target: "nemo_relay.server", + event = "server_shutdown_started", + instance_id = instance_id.as_str(); + "Gateway server shutdown started" + ); let serve_result = match shutdown { Some(shutdown) => { axum::serve(listener, app) @@ -326,7 +347,7 @@ async fn serve_listener_with_dynamic_inner( } None => axum::serve(listener, app).await, }; - finish_server_shutdown(serve_result, &sessions, plugin_activation).await + finish_server_shutdown(serve_result, &sessions, plugin_activation, &instance_id).await } fn server_shutdown_future( @@ -373,6 +394,7 @@ async fn finish_server_shutdown( serve_result: std::io::Result<()>, sessions: &SessionManager, plugin_activation: Option, + instance_id: &str, ) -> Result<(), CliError> { let close_result = sessions.close_all("gateway_shutdown").await; let flush_result = nemo_relay::api::runtime::flush_subscribers().map_err(CliError::from); @@ -380,20 +402,85 @@ async fn finish_server_shutdown( .map(ServerPluginActivation::clear) .unwrap_or(Ok(())); if let Err(serve_error) = serve_result { + log::error!( + target: "nemo_relay.server", + event = "server_failed", + instance_id, + error_kind = "io"; + "Gateway server failed" + ); if let Err(close_error) = close_result { - eprintln!("session teardown failed after server error: {close_error}"); + log::error!( + target: "nemo_relay.server", + event = "server_teardown_failed", + instance_id, + component = "sessions", + error_kind = close_error.log_kind(); + "Gateway server teardown failed" + ); } if let Err(flush_error) = flush_result { - eprintln!("subscriber flush failed after server error: {flush_error}"); + log::error!( + target: "nemo_relay.server", + event = "server_teardown_failed", + instance_id, + component = "subscribers", + error_kind = flush_error.log_kind(); + "Gateway server teardown failed" + ); } if let Err(clear_error) = clear_result { - eprintln!("plugin teardown failed after server error: {clear_error}"); + log::error!( + target: "nemo_relay.server", + event = "server_teardown_failed", + instance_id, + component = "plugins", + error_kind = clear_error.log_kind(); + "Gateway server teardown failed" + ); } return Err(serve_error.into()); } + if let Err(error) = &close_result { + log::error!( + target: "nemo_relay.server", + event = "server_teardown_failed", + instance_id, + component = "sessions", + error_kind = error.log_kind(); + "Gateway server teardown failed" + ); + } + if let Err(error) = &flush_result { + log::error!( + target: "nemo_relay.server", + event = "server_teardown_failed", + instance_id, + component = "subscribers", + error_kind = error.log_kind(); + "Gateway server teardown failed" + ); + } + if let Err(error) = &clear_result { + log::error!( + target: "nemo_relay.server", + event = "server_teardown_failed", + instance_id, + component = "plugins", + error_kind = error.log_kind(); + "Gateway server teardown failed" + ); + } close_result?; flush_result?; - clear_result + clear_result?; + log::info!( + target: "nemo_relay.server", + event = "server_stopped", + instance_id; + "Gateway server stopped" + ); + Ok(()) } async fn shutdown_signal() { @@ -486,8 +573,17 @@ impl AppState { headers: &mut HeaderMap, ) -> Result { if let Some(proxy) = &self.transparent_proxy_credential { + let source_credential = proxy.consume(headers).inspect_err(|error| { + log::warn!( + target: "nemo_relay.gateway", + event = "request_rejected", + reason = "transparent_proxy_authentication", + error_kind = error.log_kind(); + "Gateway request was rejected during transparent proxy authentication" + ); + })?; return Ok(crate::provider_auth::ProviderRequestAuthorization { - source_credential: proxy.consume(headers)?, + source_credential, allow_environment_provider_auth: true, }); } diff --git a/crates/cli/src/sessions/mod.rs b/crates/cli/src/sessions/mod.rs index 77a0b1bf3..732f9c31e 100644 --- a/crates/cli/src/sessions/mod.rs +++ b/crates/cli/src/sessions/mod.rs @@ -311,7 +311,13 @@ impl SessionManager { ) .await { - eprintln!("nemo-relay CLI gateway: idle session teardown failed: {error}"); + log::warn!( + target: "nemo_relay.session", + event = "session_cleanup_failed", + reason = "idle_timeout", + error_kind = error.log_kind(); + "Idle session cleanup failed" + ); } } }); @@ -501,13 +507,26 @@ impl SessionManager { if finish == GatewaySessionFinish::Close && let Some(session) = closing.as_mut() - && let Err(error) = session + { + match session .close_for_shutdown("uncorrelated_gateway_call_complete") .await - { - eprintln!( - "nemo-relay CLI gateway: failed to close isolated session {session_id}: {error}" - ); + { + Ok(()) => log::info!( + target: "nemo_relay.session", + event = "session_closed", + session_id = session_id; + "Session closed" + ), + Err(error) => log::warn!( + target: "nemo_relay.session", + event = "session_cleanup_failed", + session_id = session_id, + reason = "isolated_session_close", + error_kind = error.log_kind(); + "Session cleanup failed" + ), + } } } @@ -1321,9 +1340,13 @@ impl Session { return Ok(()); } if !self.subagents.contains_key(&event.subagent_id) { - eprintln!( - "nemo-relay CLI gateway: received {} for subagent {} without a matching start", - event.event_name, event.subagent_id + log::warn!( + target: "nemo_relay.session", + event = "session_correlation_failed", + session_id = event.session_id.as_str(), + subagent_id = event.subagent_id.as_str(), + lifecycle_event = event.event_name.as_str(); + "Subagent lifecycle event had no matching start" ); if self.agent_kind == AgentKind::ClaudeCode && self.turn_scope.is_none() { return Ok(()); diff --git a/crates/cli/tests/architecture_tests.rs b/crates/cli/tests/architecture_tests.rs index bc4633127..45e9a83e2 100644 --- a/crates/cli/tests/architecture_tests.rs +++ b/crates/cli/tests/architecture_tests.rs @@ -255,6 +255,175 @@ fn all_target_is_command_only() { } } +const OPERATIONAL_LOG_TARGETS: &[&str] = &[ + "nemo_relay.logging", + "nemo_relay.runtime", + "nemo_relay.plugin", + "nemo_relay.worker", + "nemo_relay.observability", + "nemo_relay.cli", + "nemo_relay.configuration", + "nemo_relay.server", + "nemo_relay.gateway", + "nemo_relay.session", + "nemo_relay.agent", + "nemo_relay.bootstrap", + "nemo_relay.mcp", + "nemo_relay.hook", + "nemo_relay.installation", + "nemo_relay.diagnostics", +]; + +#[derive(Default)] +struct LogMacroVisitor { + failures: Vec, +} + +impl<'ast> Visit<'ast> for LogMacroVisitor { + fn visit_macro(&mut self, item: &'ast syn::Macro) { + let path = item + .path + .segments + .iter() + .map(|segment| segment.ident.to_string()) + .collect::>() + .join("::"); + let macro_name = path.rsplit("::").next().unwrap_or_default(); + if matches!(macro_name, "info" | "warn" | "error" | "debug" | "trace") { + let tokens = item.tokens.to_string(); + if matches!(macro_name, "debug" | "trace") { + self.failures + .push(format!("production call site uses {path}!")); + } + let target = string_field(&tokens, "target :"); + if target + .as_deref() + .is_none_or(|target| !OPERATIONAL_LOG_TARGETS.contains(&target)) + { + self.failures.push(format!( + "{path}! has an invalid or missing target: {tokens}" + )); + } + let event = string_field(&tokens, "event ="); + if event.as_deref().is_none_or(|event| !is_snake_case(event)) { + self.failures + .push(format!("{path}! has an invalid or missing event: {tokens}")); + } + for field in [ + "error =", + "payload =", + "body =", + "headers =", + "credentials =", + "configuration =", + "environment =", + "argv =", + ] { + if tokens.contains(field) { + self.failures.push(format!( + "{path}! uses privacy-sensitive field {field:?}: {tokens}" + )); + } + } + } + syn::visit::visit_macro(self, item); + } +} + +fn string_field(tokens: &str, marker: &str) -> Option { + let suffix = tokens.split_once(marker)?.1.trim_start(); + let suffix = suffix.strip_prefix('"')?; + Some(suffix.split_once('"')?.0.to_string()) +} + +fn is_snake_case(value: &str) -> bool { + !value.is_empty() + && !value.starts_with('_') + && !value.ends_with('_') + && value + .bytes() + .all(|byte| byte.is_ascii_lowercase() || byte.is_ascii_digit() || byte == b'_') +} + +#[test] +fn operational_log_calls_follow_the_stable_contract() { + let crate_root = Path::new(env!("CARGO_MANIFEST_DIR")); + for src in [ + crate_root.join("src"), + crate_root.join("../core/src"), + crate_root.join("../adaptive/src"), + crate_root.join("../pii-redaction/src"), + ] { + for path in rust_files(&src) { + let source = fs::read_to_string(&path).unwrap(); + let file = syn::parse_file(&source).unwrap(); + let mut visitor = LogMacroVisitor::default(); + visitor.visit_file(&file); + assert!( + visitor.failures.is_empty(), + "{}: {}", + path.display(), + visitor.failures.join("; ") + ); + } + } +} + +#[test] +fn operational_direct_stderr_is_limited_to_emergency_and_ui_boundaries() { + let crate_root = Path::new(env!("CARGO_MANIFEST_DIR")); + let allowed_cli = [ + "src/lib.rs", + "src/commands/mod.rs", + "src/agents/codex/launch.rs", + "src/hooks/delivery.rs", + "src/hooks/response.rs", + "src/plugins/lifecycle/render.rs", + ]; + for path in rust_files(&crate_root.join("src")) { + let source = fs::read_to_string(&path).unwrap(); + if source.contains("eprintln!") { + let relative = path.strip_prefix(crate_root).unwrap(); + assert!( + allowed_cli + .iter() + .any(|allowed| relative == Path::new(allowed)), + "operational direct stderr found in {}", + path.display() + ); + } + } + for path in rust_files(&crate_root.join("../core/src")) { + let source = fs::read_to_string(&path).unwrap(); + assert!( + !source.contains("eprintln!"), + "core operational direct stderr found in {}", + path.display() + ); + } + for (root, allowed) in [ + ( + crate_root.join("../adaptive/src"), + ["src/acg/debug.rs"].as_slice(), + ), + (crate_root.join("../pii-redaction/src"), [].as_slice()), + ] { + for path in rust_files(&root) { + let source = fs::read_to_string(&path).unwrap(); + if source.contains("eprintln!") { + let relative = path.strip_prefix(&root).unwrap(); + assert!( + allowed + .iter() + .any(|allowed| relative == Path::new(allowed.trim_start_matches("src/"))), + "operational direct stderr found in {}", + path.display() + ); + } + } + } +} + #[test] fn shared_runtime_subsystems_do_not_dispatch_host_variants() { let src = source_root(); diff --git a/crates/cli/tests/cli_tests.rs b/crates/cli/tests/cli_tests.rs index 5f1ca104c..1575da4f4 100644 --- a/crates/cli/tests/cli_tests.rs +++ b/crates/cli/tests/cli_tests.rs @@ -53,6 +53,37 @@ fn toml_basic_string(value: &str) -> String { format!("\"{escaped}\"") } +fn write_jsonl_logging_config(temp: &Path) -> (std::path::PathBuf, std::path::PathBuf) { + let config_path = temp.join("logging.toml"); + let log_path = temp.join("operational.jsonl"); + std::fs::write( + &config_path, + format!( + r#"[logging] +level = "info" +stderr_format = "jsonl" + +[[logging.sinks]] +path = {} +level = "info" +format = "jsonl" +queue_capacity = 64 +"#, + toml_basic_string(log_path.to_string_lossy().as_ref()) + ), + ) + .unwrap(); + (config_path, log_path) +} + +fn read_jsonl_records(path: &Path) -> Vec { + std::fs::read_to_string(path) + .unwrap() + .lines() + .map(|line| serde_json::from_str(line).unwrap()) + .collect() +} + fn write_dynamic_plugin_manifest(dir: &std::path::Path, plugin_id: &str) { write_dynamic_plugin_manifest_with_options(dir, plugin_id, &["plugin_worker"], None); } @@ -224,6 +255,96 @@ fn cli_version_exits_successfully() { assert!(String::from_utf8_lossy(&output.stdout).contains("nemo-relay ")); } +#[test] +fn cli_jsonl_logging_records_successful_command_lifecycle_without_leaking_secrets() { + let temp = tempfile::tempdir().unwrap(); + let (config_path, log_path) = write_jsonl_logging_config(temp.path()); + let secret = "NEMO_RELAY_SECRET_SENTINEL_7a91"; + let output = Command::new(gateway_bin()) + .env("XDG_CONFIG_HOME", temp.path().join("xdg")) + .env("HOME", temp.path()) + .env("NEMO_RELAY_TEST_SECRET", secret) + .args(["--log-config-path"]) + .arg(&config_path) + .args(["agents", "--json"]) + .output() + .unwrap(); + + assert!(output.status.success()); + serde_json::from_slice::(&output.stdout).unwrap(); + let contents = std::fs::read_to_string(&log_path).unwrap(); + assert!(!contents.contains(secret)); + let records = read_jsonl_records(&log_path); + for event in [ + "logging_initialized", + "command_started", + "diagnostics_completed", + "command_completed", + "logging_shutdown_started", + ] { + assert!( + records.iter().any(|record| record["event"] == event), + "missing {event}: {records:?}" + ); + } + let positions = [ + "logging_initialized", + "command_started", + "diagnostics_completed", + "command_completed", + "logging_shutdown_started", + ] + .map(|event| { + records + .iter() + .position(|record| record["event"] == event) + .expect("lifecycle event was asserted above") + }); + assert!( + positions.windows(2).all(|pair| pair[0] < pair[1]), + "unexpected successful command lifecycle order: {records:?}" + ); + assert!( + records + .iter() + .all(|record| { record["level"] != "debug" && record["level"] != "trace" }) + ); +} + +#[test] +fn cli_logs_final_failure_before_shutdown_and_preserves_user_error() { + let temp = tempfile::tempdir().unwrap(); + let (config_path, log_path) = write_jsonl_logging_config(temp.path()); + let secret = "NEMO_RELAY_ARGV_SECRET_SENTINEL_2c48"; + let catalog = temp.path().join(format!("{secret}.json")); + std::fs::write(&catalog, format!(r#"{{"secret":"{secret}"}}"#)).unwrap(); + let output = Command::new(gateway_bin()) + .args(["--log-config-path"]) + .arg(&config_path) + .args(["model-pricing", "validate"]) + .arg(&catalog) + .output() + .unwrap(); + + assert!(!output.status.success()); + assert!(String::from_utf8_lossy(&output.stderr).contains("invalid model pricing catalog")); + let contents = std::fs::read_to_string(&log_path).unwrap(); + assert!(!contents.contains(secret)); + let records = read_jsonl_records(&log_path); + let failed = records + .iter() + .position(|record| record["event"] == "command_failed") + .expect("command_failed record"); + let shutdown = records + .iter() + .position(|record| record["event"] == "logging_shutdown_started") + .expect("logging_shutdown_started record"); + assert!(failed < shutdown); + assert_eq!(records[failed]["target"], "nemo_relay.cli"); + assert_eq!(records[failed]["level"], "error"); + assert_eq!(records[failed]["fields"]["command"], "model_pricing"); +} + #[test] fn managed_mcp_launch_removes_unresolved_environment_placeholders_before_cli_parsing() { let output = Command::new(gateway_bin()) diff --git a/crates/cli/tests/coverage/agents/launcher_tests.rs b/crates/cli/tests/coverage/agents/launcher_tests.rs index a15eb2c93..13bdebddc 100644 --- a/crates/cli/tests/coverage/agents/launcher_tests.rs +++ b/crates/cli/tests/coverage/agents/launcher_tests.rs @@ -18,6 +18,7 @@ struct EnvScope { impl EnvScope { fn set(values: &[(&'static str, Option<&std::ffi::OsStr>)]) -> Self { + crate::test_support::enable_operational_logs(); let guard = crate::test_support::ENV_TEST_LOCK .lock() .unwrap_or_else(|error| error.into_inner()); @@ -1606,6 +1607,7 @@ fn hook_write_helpers_cover_toml_escaping() { #[cfg(unix)] #[test] fn exit_code_preserves_normal_and_shell_wrapped_codes() { + let _cwd = crate::test_support::CwdTestScope::locked(); let status = std::process::Command::new("/bin/sh") .args(["-c", "exit 7"]) .status() @@ -1623,8 +1625,10 @@ fn exit_code_preserves_normal_and_shell_wrapped_codes() { // Windows `.cmd` argv delivery is covered independently by `agent_process_tests`. #[cfg(unix)] #[tokio::test] +#[allow(clippy::await_holding_lock)] async fn run_starts_gateway_injects_env_and_returns_agent_exit_code() { let temp = tempfile::tempdir().unwrap(); + let _cwd = crate::test_support::CwdTestScope::locked(); let config = temp.path().join("config.toml"); std::fs::write(&config, "[upstream]\n").unwrap(); let output = temp.path().join("env.txt"); @@ -1800,8 +1804,10 @@ async fn wait_for_health_reports_unready_gateway() { #[cfg(unix)] #[tokio::test] +#[allow(clippy::await_holding_lock)] async fn gateway_failure_terminates_the_agent_and_restores_private_state() { let temp = tempfile::tempdir().unwrap(); + let _cwd = crate::test_support::CwdTestScope::locked(); let wrapper_pid_path = temp.path().join("wrapper.pid"); let descendant_pid_path = temp.path().join("descendant.pid"); let script = temp.path().join("test-agent"); @@ -1874,8 +1880,10 @@ async fn gateway_failure_terminates_the_agent_and_restores_private_state() { } #[tokio::test] +#[allow(clippy::await_holding_lock)] async fn execute_live_run_reports_gateway_startup_error_when_health_check_fails() { let _guard = crate::test_support::PLUGIN_CONFIG_TEST_LOCK.lock().await; + let _cwd = crate::test_support::CwdTestScope::locked(); let _env = EnvScope::without_managed_bootstrap(); let _ = nemo_relay::plugin::clear_plugin_configuration(); let resolved = ResolvedConfig { @@ -1911,18 +1919,33 @@ async fn execute_live_run_reports_gateway_startup_error_when_health_check_fails( ..GatewayConfig::default() }; - let error = execute_live_run(listener, gateway_config, &gateway_url, prepared) - .await - .unwrap_err() - .to_string(); + let error = TransparentRun { + agent: CodingAgent::ClaudeCode, + prepared, + resolved: ResolvedConfig { + gateway: gateway_config, + ..resolved + }, + dynamic_plugins: Vec::new(), + listener, + gateway_url, + dry_run: false, + print: false, + } + .execute() + .await + .unwrap_err() + .to_string(); assert!(error.contains("ATOF mode")); assert!(!error.contains("gateway did not become ready")); } #[tokio::test] +#[allow(clippy::await_holding_lock)] async fn execute_live_run_removes_hermes_overlay_when_health_check_fails() { let _guard = crate::test_support::PLUGIN_CONFIG_TEST_LOCK.lock().await; + let _cwd = crate::test_support::CwdTestScope::locked(); let _env = EnvScope::without_managed_bootstrap(); let _ = nemo_relay::plugin::clear_plugin_configuration(); let temp = tempfile::tempdir().unwrap(); diff --git a/crates/cli/tests/coverage/agents/plugin_install_tests.rs b/crates/cli/tests/coverage/agents/plugin_install_tests.rs index 1f2ecc010..8af743d26 100644 --- a/crates/cli/tests/coverage/agents/plugin_install_tests.rs +++ b/crates/cli/tests/coverage/agents/plugin_install_tests.rs @@ -215,6 +215,7 @@ fn replacement_generation_guard_removes_an_owned_lock_after_marker_removal() { #[test] fn replacement_generation_guard_retains_its_lock_when_marker_state_is_uncertain() { + crate::test_support::enable_operational_logs(); let dir = tempdir().unwrap(); let marker = dir.path().join("generation-marker"); let lock = dir.path().join("generation.lock"); @@ -229,6 +230,51 @@ fn replacement_generation_guard_retains_its_lock_when_marker_state_is_uncertain( assert!(lock.exists()); } +#[test] +#[cfg(unix)] +fn replacement_generation_guard_retains_its_lock_when_marker_is_inaccessible() { + use std::os::unix::fs::PermissionsExt as _; + + struct PermissionRestore(std::path::PathBuf); + + impl Drop for PermissionRestore { + fn drop(&mut self) { + let _ = std::fs::set_permissions(&self.0, std::fs::Permissions::from_mode(0o700)); + } + } + + crate::test_support::enable_operational_logs(); + let dir = tempdir().unwrap(); + let marker_parent = dir.path().join("marker-parent"); + std::fs::create_dir(&marker_parent).unwrap(); + let marker = marker_parent.join("generation-marker"); + let lock = dir.path().join("generation.lock"); + crate::installation::generation::write_new_generation_with_token_at(&marker, &lock).unwrap(); + let guard = + acquire_replacement_generation_lock(CodingAgent::Codex, &marker, &lock, true).unwrap(); + + std::fs::set_permissions(&marker_parent, std::fs::Permissions::from_mode(0o000)).unwrap(); + let _permissions = PermissionRestore(marker_parent.clone()); + if std::fs::read_dir(&marker_parent).is_ok() { + return; + } + drop(guard); + + assert!(lock.exists()); +} + +#[test] +fn best_effort_generation_lock_cleanup_reports_directory_removal_failure() { + crate::test_support::enable_operational_logs(); + let dir = tempdir().unwrap(); + let lock = dir.path().join("generation.lock"); + std::fs::create_dir(&lock).unwrap(); + + remove_generation_lock_best_effort(&lock); + + assert!(lock.is_dir()); +} + #[test] fn codex_plugin_requires_version_with_complete_hook_support() { let dir = tempdir().unwrap(); @@ -893,6 +939,7 @@ impl MockSetupRunner { } fn options(dir: &Path) -> PluginInstallOptions { + crate::test_support::enable_operational_logs(); PluginInstallOptions { install_dir: dir.to_path_buf(), operation_lock_dir: dir.join("operation-locks"), @@ -1009,6 +1056,7 @@ fn corrupt_generation_fence(path: &Path, corruption: &str) { struct CrossProcessLockHolder { child: Option, release: PathBuf, + _cwd: crate::test_support::CwdTestScope, } impl CrossProcessLockHolder { @@ -1018,6 +1066,7 @@ impl CrossProcessLockHolder { global_lock_dir: Option<&Path>, synchronization_dir: &Path, ) -> Self { + let cwd = crate::test_support::CwdTestScope::locked(); let ready = synchronization_dir.join("ready"); let release = synchronization_dir.join("release"); let mut command = Command::new(std::env::current_exe().unwrap()); @@ -1053,6 +1102,7 @@ impl CrossProcessLockHolder { Self { child: Some(child), release, + _cwd: cwd, } } @@ -1979,6 +2029,7 @@ fn host_registration_report_surfaces_capture_status_and_stderr_variants() { #[test] fn top_level_install_uninstall_and_doctor_report_empty_host_selection() { + crate::test_support::enable_operational_logs(); let dir = tempdir().unwrap(); let empty_path = dir.path().join("empty-path"); std::fs::create_dir_all(&empty_path).unwrap(); @@ -2019,6 +2070,40 @@ fn top_level_install_uninstall_and_doctor_report_empty_host_selection() { assert_eq!(CodingAgent::Codex.as_arg(), "codex"); assert_eq!(CodingAgent::Codex.label(), "Codex"); assert_eq!(CodingAgent::Codex.executable(), "codex"); + + assert_eq!( + uninstall( + CodingAgent::Codex, + crate::installation::UninstallRequest { + install_dir: Some(dir.path().join("dry-run-uninstall")), + dry_run: true, + }, + ) + .unwrap(), + std::process::ExitCode::SUCCESS + ); + + let install_error = install( + CodingAgent::Codex, + crate::installation::InstallRequest { + install_dir: Some(dir.path().join("failed-install")), + force: false, + dry_run: false, + skip_doctor: true, + }, + ) + .expect_err("an unavailable host CLI should fail installation"); + assert!(matches!(install_error, CliError::Install(_))); + + let uninstall_error = uninstall( + CodingAgent::Codex, + crate::installation::UninstallRequest { + install_dir: Some(dir.path().join("failed-uninstall")), + dry_run: false, + }, + ) + .expect_err("an unavailable host CLI should fail uninstallation"); + assert!(matches!(uninstall_error, CliError::Install(_))); } #[test] diff --git a/crates/cli/tests/coverage/commands/main_tests.rs b/crates/cli/tests/coverage/commands/main_tests.rs index 9d1822312..cd5f8c30c 100644 --- a/crates/cli/tests/coverage/commands/main_tests.rs +++ b/crates/cli/tests/coverage/commands/main_tests.rs @@ -13,6 +13,17 @@ use crate::commands::plugins::{ PluginsSubcommand, PluginsValidateCommand, }; +#[test] +fn operational_command_names_cover_logging_exempt_commands() { + for (args, expected) in [ + (vec!["nemo-relay", "codex"], "codex"), + (vec!["nemo-relay", "config"], "config"), + ] { + let cli = Cli::try_parse_from(args).unwrap(); + assert_eq!(cli.command.unwrap().log_name(), expected); + } +} + #[test] fn bootstrap_shutdown_token_is_removed_before_runtime_startup() { let _environment = crate::test_support::EnvScope::set(&[( diff --git a/crates/cli/tests/coverage/shared/bootstrap_tests.rs b/crates/cli/tests/coverage/shared/bootstrap_tests.rs index 8bccfe064..24f8feaf4 100644 --- a/crates/cli/tests/coverage/shared/bootstrap_tests.rs +++ b/crates/cli/tests/coverage/shared/bootstrap_tests.rs @@ -10,6 +10,7 @@ use std::process::Command; #[test] fn failed_reaper_spawn_terminates_and_reaps_the_retained_child() { + let _cwd = crate::test_support::CwdTestScope::locked(); let child = Command::new(std::env::current_exe().unwrap()) .arg("--list") .stdout(Stdio::null()) @@ -34,6 +35,7 @@ fn failed_reaper_spawn_terminates_and_reaps_the_retained_child() { #[test] fn persistent_gateway_requires_a_loopback_endpoint() { + crate::test_support::enable_operational_logs(); let non_loopback = GatewaySpec::new("0.0.0.0:47632".parse().unwrap()) .acquire() .unwrap_err(); @@ -42,6 +44,7 @@ fn persistent_gateway_requires_a_loopback_endpoint() { #[test] fn compatible_gateway_is_reused_without_starting_another_process() { + crate::test_support::enable_operational_logs(); let temp = tempfile::tempdir().unwrap(); let config = temp.path().join("config"); let _environment = EnvScope::set(&[ @@ -84,6 +87,7 @@ fn compatible_gateway_is_reused_without_starting_another_process() { #[test] fn foreign_and_incompatible_listeners_are_never_adopted() { + crate::test_support::enable_operational_logs(); for (status, body, expected) in [ ("200 OK", "{}", "not a compatible"), ( diff --git a/crates/cli/tests/coverage/shared/doctor_tests.rs b/crates/cli/tests/coverage/shared/doctor_tests.rs index 5d06e5e2d..f5a2b12f1 100644 --- a/crates/cli/tests/coverage/shared/doctor_tests.rs +++ b/crates/cli/tests/coverage/shared/doctor_tests.rs @@ -693,6 +693,7 @@ fn collect_environment_and_completions_cover_missing_home_and_unknown_shell() { #[allow(clippy::await_holding_lock)] async fn collect_agents_filters_target_and_records_version() { let temp = tempfile::tempdir().unwrap(); + let _cwd = crate::test_support::CwdTestScope::locked(); let codex = temp.path().join("codex"); std::fs::write(&codex, "#!/bin/sh\nprintf 'codex-cli 0.143.0\\n'\n").unwrap(); make_executable(&codex); @@ -710,8 +711,10 @@ async fn collect_agents_filters_target_and_records_version() { #[cfg(unix)] #[tokio::test] +#[allow(clippy::await_holding_lock)] async fn collect_agents_preserves_wrapper_argv_for_version_validation() { let temp = tempfile::tempdir().unwrap(); + let _cwd = crate::test_support::CwdTestScope::locked(); let wrapper = temp.path().join("npx"); std::fs::write( &wrapper, @@ -734,6 +737,7 @@ async fn collect_agents_preserves_wrapper_argv_for_version_validation() { #[allow(clippy::await_holding_lock)] async fn collect_agents_distinguishes_required_and_optional_version_failures() { let temp = tempfile::tempdir().unwrap(); + let _cwd = crate::test_support::CwdTestScope::locked(); let codex = temp.path().join("codex"); std::fs::write(&codex, "#!/bin/sh\nprintf 'codex-cli 0.1.0\\n'\n").unwrap(); make_executable(&codex); diff --git a/crates/cli/tests/coverage/shared/error_tests.rs b/crates/cli/tests/coverage/shared/error_tests.rs new file mode 100644 index 000000000..7b81f28ab --- /dev/null +++ b/crates/cli/tests/coverage/shared/error_tests.rs @@ -0,0 +1,82 @@ +// SPDX-FileCopyrightText: Copyright (c) 2026, NVIDIA CORPORATION & AFFILIATES. All rights reserved. +// SPDX-License-Identifier: Apache-2.0 + +use std::collections::BTreeMap; + +use nemo_relay::error::{FlowError, UpstreamFailure, UpstreamFailureClass}; +use nemo_relay::observability::openinference::OpenInferenceError; + +use super::*; + +#[test] +fn log_kinds_cover_every_operational_error_class() { + let upstream = reqwest::Client::new() + .get("not a valid URL") + .build() + .expect_err("invalid URL should produce a reqwest error"); + let http = http::Request::builder() + .uri("not a valid URI") + .body(()) + .expect_err("invalid URI should produce an HTTP error"); + let errors = [ + ( + CliError::GuardrailRejected("blocked".into()), + "guardrail_rejected", + ), + ( + CliError::InvalidPayload("invalid".into()), + "invalid_payload", + ), + ( + CliError::PayloadTooLarge("large".into()), + "payload_too_large", + ), + ( + CliError::Unauthorized("missing token".into()), + "unauthorized", + ), + (CliError::Upstream(upstream), "upstream"), + ( + CliError::ProviderFailure(UpstreamFailure { + status: Some(503), + body: "unavailable".into(), + headers: BTreeMap::new(), + class: UpstreamFailureClass::ModelUnavailable, + }), + "provider_failure", + ), + (CliError::Http(http), "http"), + (CliError::Io(std::io::Error::other("io")), "io"), + (CliError::Install("install".into()), "install"), + (CliError::Config("config".into()), "configuration"), + (CliError::Launch("launch".into()), "launch"), + ( + CliError::HookDelivery { + source: Box::new(CliError::Install("hook transport".into())), + }, + "install", + ), + ( + CliError::PluginLifecycle { + command: "add", + target: None, + kind: PluginLifecycleFailureKind::Failed, + code: None, + message: "plugin".into(), + }, + "plugin_lifecycle", + ), + ( + CliError::Flow(FlowError::Internal("runtime".into())), + "runtime", + ), + ( + CliError::OpenInference(OpenInferenceError::Provider("export".into())), + "openinference", + ), + ]; + + for (error, expected) in errors { + assert_eq!(error.log_kind(), expected); + } +} diff --git a/crates/cli/tests/coverage/shared/gateway_tests.rs b/crates/cli/tests/coverage/shared/gateway_tests.rs index c5ccd467e..246073441 100644 --- a/crates/cli/tests/coverage/shared/gateway_tests.rs +++ b/crates/cli/tests/coverage/shared/gateway_tests.rs @@ -16,6 +16,7 @@ use serde_json::Map; use tokio::io::{AsyncReadExt, AsyncWriteExt}; fn test_http_client() -> Client { + crate::test_support::enable_operational_logs(); Client::new() } diff --git a/crates/cli/tests/coverage/shared/mcp_tests.rs b/crates/cli/tests/coverage/shared/mcp_tests.rs index 329f025c4..f506344f9 100644 --- a/crates/cli/tests/coverage/shared/mcp_tests.rs +++ b/crates/cli/tests/coverage/shared/mcp_tests.rs @@ -22,6 +22,7 @@ struct BootstrapConfigHome { impl BootstrapConfigHome { fn enter(path: &std::path::Path) -> Self { + crate::test_support::enable_operational_logs(); let guard = crate::test_support::ENV_TEST_LOCK .lock() .unwrap_or_else(std::sync::PoisonError::into_inner); @@ -52,6 +53,7 @@ struct TransparentRunEnvironment { impl TransparentRunEnvironment { fn without_gateway() -> Self { + crate::test_support::enable_operational_logs(); let guard = crate::test_support::ENV_TEST_LOCK .lock() .unwrap_or_else(std::sync::PoisonError::into_inner); diff --git a/crates/cli/tests/coverage/shared/server_tests.rs b/crates/cli/tests/coverage/shared/server_tests.rs index 92742338a..a18bdbe8a 100644 --- a/crates/cli/tests/coverage/shared/server_tests.rs +++ b/crates/cli/tests/coverage/shared/server_tests.rs @@ -158,6 +158,7 @@ impl Drop for TestServer { } fn test_config() -> GatewayConfig { + crate::test_support::enable_operational_logs(); GatewayConfig { bind: "127.0.0.1:0".parse().unwrap(), openai_base_url: "http://127.0.0.1".into(), @@ -198,6 +199,21 @@ fn startup_status_reports_bound_gateway_and_exporters() { assert!(output.contains("OpenTelemetry http://127.0.0.1:4318/v1/traces")); } +#[tokio::test] +async fn failed_server_result_is_reported_after_successful_teardown() { + let sessions = SessionManager::new(test_config()); + let error = finish_server_shutdown( + Err(std::io::Error::other("listener failed")), + &sessions, + None, + "test-instance", + ) + .await + .expect_err("server failure should be preserved after teardown"); + + assert!(matches!(error, CliError::Io(_))); +} + #[test] fn startup_status_reports_not_configured_when_no_exporters() { let output = render_startup_status("127.0.0.1:4567".parse().unwrap(), &test_config(), false); diff --git a/crates/cli/tests/coverage/shared/session_tests.rs b/crates/cli/tests/coverage/shared/session_tests.rs index f847bdd9b..4bb94ab37 100644 --- a/crates/cli/tests/coverage/shared/session_tests.rs +++ b/crates/cli/tests/coverage/shared/session_tests.rs @@ -6228,6 +6228,7 @@ fn weak_subagent_start_status_does_not_teach_request_affinity() { #[tokio::test] async fn gateway_shutdown_attempts_remaining_sessions_after_close_error() { + crate::test_support::enable_operational_logs(); let subscriber_name = "cli-close-all-deferred-error-test"; let _ = deregister_subscriber(subscriber_name); @@ -6871,6 +6872,7 @@ fn merge_metadata_handles_objects_nulls_and_scalars() { } fn session_test_config() -> GatewayConfig { + crate::test_support::enable_operational_logs(); GatewayConfig { bind: "127.0.0.1:0".parse().unwrap(), openai_base_url: "http://127.0.0.1".into(), diff --git a/crates/cli/tests/coverage/shared/test_support.rs b/crates/cli/tests/coverage/shared/test_support.rs index a76959793..fe5e1ab59 100644 --- a/crates/cli/tests/coverage/shared/test_support.rs +++ b/crates/cli/tests/coverage/shared/test_support.rs @@ -6,9 +6,20 @@ use std::io::Read; use std::net::TcpListener; use std::path::{Path, PathBuf}; use std::sync::atomic::{AtomicBool, Ordering}; -use std::sync::{Mutex, MutexGuard}; +use std::sync::{Mutex, MutexGuard, Once}; use std::time::{Duration, Instant}; +static TEST_LOGGING: Once = Once::new(); + +pub(crate) fn enable_operational_logs() { + TEST_LOGGING.call_once(|| { + let runtime = + nemo_relay::logging::init_logging(&nemo_relay::logging::LoggingConfig::default()) + .expect("test logging should initialize"); + Box::leak(Box::new(runtime)); + }); +} + #[must_use] pub(crate) struct CwdTestScope { _guard: MutexGuard<'static, ()>, diff --git a/crates/core/src/api/llm.rs b/crates/core/src/api/llm.rs index 971c8f183..9e289f948 100644 --- a/crates/core/src/api/llm.rs +++ b/crates/core/src/api/llm.rs @@ -360,9 +360,13 @@ fn project_llm_request_to_current_user_turn( if let Some(codec) = request_codec { match codec.encode(annotation, request) { Ok(encoded) => *request = encoded, - Err(error) => { - eprintln!( - "nemo_relay: LLM request projection encode failed; preserving full event history: {error}" + Err(_) => { + log::warn!( + target: "nemo_relay.observability", + event = "projection_failed", + projection = "llm_current_turn", + recovery = "preserve_full_history"; + "LLM request projection failed; preserving full event history" ); *annotation = original_annotation .expect("codec-backed projection should preserve the original annotation") @@ -507,8 +511,14 @@ fn emit_optimization_marks_with( if contributions.is_empty() { return; } - if let Err(error) = ensure_runtime_owner() { - eprintln!("nemo_relay: unable to emit LLM optimization marks: {error}"); + if ensure_runtime_owner().is_err() { + log::warn!( + target: "nemo_relay.observability", + event = "optimization_marks_skipped", + reason = "runtime_owner_unavailable", + contribution_count = contributions.len(); + "LLM optimization marks were skipped" + ); return; } for (contribution, recorded_at) in contributions { diff --git a/crates/core/src/api/runtime/subscriber_dispatcher.rs b/crates/core/src/api/runtime/subscriber_dispatcher.rs index 2d741072c..ffb4ef3b0 100644 --- a/crates/core/src/api/runtime/subscriber_dispatcher.rs +++ b/crates/core/src/api/runtime/subscriber_dispatcher.rs @@ -11,6 +11,7 @@ mod native { use std::cell::Cell; use std::panic::{AssertUnwindSafe, catch_unwind}; use std::sync::OnceLock; + use std::sync::atomic::{AtomicBool, Ordering}; use std::sync::mpsc::{self, Receiver, Sender}; use super::*; @@ -33,6 +34,7 @@ mod native { static DISPATCHER: OnceLock, String>> = OnceLock::new(); + static DISPATCHER_FAILURE_LOGGED: AtomicBool = AtomicBool::new(false); thread_local! { static IN_DISPATCHER: Cell = const { Cell::new(false) }; @@ -49,17 +51,28 @@ mod native { }; match dispatcher_sender() { Ok(sender) => { - if let Err(error) = sender.send(message) { - eprintln!("nemo_relay: failed to queue subscriber event: {error}"); + if sender.send(message).is_err() { + log::warn!( + target: "nemo_relay.runtime", + event = "subscriber_event_dropped", + reason = "dispatcher_disconnected"; + "Subscriber event was dropped because the dispatcher stopped" + ); false } else { true } } - Err(error) => { - eprintln!("nemo_relay: failed to start subscriber dispatcher: {error}"); + Err(_error) if !DISPATCHER_FAILURE_LOGGED.swap(true, Ordering::AcqRel) => { + log::error!( + target: "nemo_relay.runtime", + event = "subscriber_dispatcher_failed", + error_kind = "initialization"; + "Subscriber dispatcher failed to start" + ); false } + Err(_) => false, } } @@ -91,11 +104,19 @@ mod native { fn start_dispatcher() -> std::result::Result, String> { let (tx, rx) = mpsc::channel::(); - std::thread::Builder::new() + let sender = std::thread::Builder::new() .name("nemo-relay-subscriber-dispatcher".into()) .spawn(move || run_dispatcher(rx)) .map(|_| tx) - .map_err(|error| error.to_string()) + .map_err(|error| error.to_string()); + if sender.is_ok() { + log::info!( + target: "nemo_relay.runtime", + event = "subscriber_dispatcher_started"; + "Subscriber dispatcher started" + ); + } + sender } fn run_dispatcher(rx: Receiver) { @@ -147,7 +168,11 @@ mod native { IN_DISPATCHER.with(|flag| flag.set(true)); for subscriber in subscribers { if catch_unwind(AssertUnwindSafe(|| subscriber(&event))).is_err() { - eprintln!("nemo_relay: event subscriber callback panicked"); + log::error!( + target: "nemo_relay.runtime", + event = "subscriber_callback_panicked"; + "Event subscriber callback panicked" + ); } } IN_DISPATCHER.with(|flag| flag.set(false)); diff --git a/crates/core/src/logging/mod.rs b/crates/core/src/logging/mod.rs index 221445ab1..5c146888e 100644 --- a/crates/core/src/logging/mod.rs +++ b/crates/core/src/logging/mod.rs @@ -85,6 +85,13 @@ impl LoggingRuntime { spdlog::log_crate_proxy().set_filter(None); log::set_max_level(log_level_filter(config.level)); + log::info!( + target: "nemo_relay.logging", + event = "logging_initialized", + file_sink_count = config.sinks.len(); + "Operational logging initialized" + ); + Ok(Self { root_relay_id, logger, @@ -117,6 +124,11 @@ impl LoggingRuntime { impl Drop for LoggingRuntime { fn drop(&mut self) { + log::info!( + target: "nemo_relay.logging", + event = "logging_shutdown_started"; + "Operational logging shutdown started" + ); // Periodic flusher must stop before exit flush so it cannot race teardown. self.logger.set_flush_period(None); // `Logger::flush` only enqueues AsyncPoolSink work. `flush_on_exit` destroys the diff --git a/crates/core/src/observability/atof.rs b/crates/core/src/observability/atof.rs index d92671cf7..45f50613d 100644 --- a/crates/core/src/observability/atof.rs +++ b/crates/core/src/observability/atof.rs @@ -387,6 +387,15 @@ impl AtofExporter { } })?; let file = open_file(&path, file_sink.mode)?; + log::info!( + target: "nemo_relay.observability", + event = "storage_access_validated", + plugin_kind = "observability", + exporter = "atof", + resource_kind = "local_file", + permission = "write"; + "ATOF storage access validated" + ); (Some(path), Some(BufWriter::new(file)), Vec::new()) } AtofSinkConfig::Stream(stream_sink) => { @@ -442,12 +451,30 @@ impl AtofExporter { /// Register this exporter globally under the given subscriber name. pub fn register(&self, name: &str) -> Result<()> { - register_subscriber(name, self.subscriber()).map_err(Into::into) + register_subscriber(name, self.subscriber()).map_err(AtofExporterError::from)?; + log::info!( + target: "nemo_relay.observability", + event = "exporter_registered", + exporter = "atof", + subscriber = name; + "ATOF exporter registered" + ); + Ok(()) } /// Deregister a global subscriber by name. pub fn deregister(&self, name: &str) -> Result { - deregister_subscriber(name).map_err(Into::into) + let removed = deregister_subscriber(name).map_err(AtofExporterError::from)?; + if removed { + log::info!( + target: "nemo_relay.observability", + event = "exporter_deregistered", + exporter = "atof", + subscriber = name; + "ATOF exporter deregistered" + ); + } + Ok(removed) } /// Flush the underlying file and drain queued endpoint events. @@ -520,12 +547,21 @@ impl AtofExporter { endpoint.close(); } flush_result?; - stored_failure_result( + let result = stored_failure_result( self.path .as_deref() .unwrap_or_else(|| Path::new("")), &state, - ) + ); + if result.is_ok() { + log::info!( + target: "nemo_relay.observability", + event = "exporter_shutdown", + exporter = "atof"; + "ATOF exporter shut down" + ); + } + result } } @@ -604,6 +640,8 @@ impl NdjsonBodyMessage { struct AtofEndpointWorker { sender: tokio::sync::mpsc::UnboundedSender, timeout: Duration, + index: usize, + transport: AtofEndpointTransport, } impl AtofEndpointWorker { @@ -616,7 +654,15 @@ impl AtofEndpointWorker { if self.sender.send(EndpointMessage::Flush(tx)).is_ok() && rx.recv_timeout(self.timeout).is_err() { - eprintln!("nemo_relay: timed out flushing ATOF endpoint"); + log::warn!( + target: "nemo_relay.observability", + event = "endpoint_flush_failed", + exporter = "atof", + endpoint_index = self.index, + transport = self.transport.as_str(), + reason = "timeout"; + "ATOF endpoint flush timed out" + ); } } @@ -625,7 +671,15 @@ impl AtofEndpointWorker { if self.sender.send(EndpointMessage::Close(tx)).is_ok() && rx.recv_timeout(self.timeout).is_err() { - eprintln!("nemo_relay: timed out closing ATOF endpoint"); + log::warn!( + target: "nemo_relay.observability", + event = "endpoint_close_failed", + exporter = "atof", + endpoint_index = self.index, + transport = self.transport.as_str(), + reason = "timeout"; + "ATOF endpoint close timed out" + ); } } } @@ -637,7 +691,6 @@ fn start_endpoint_workers(configs: &[AtofStreamSinkConfig]) -> Result workers.push(worker), Err(error) => { - eprintln!("nemo_relay: invalid ATOF endpoint[{index}]: {error}"); return Err(AtofExporterError::InvalidEndpoint(format!( "endpoints[{index}]: {error}" ))); @@ -653,7 +706,6 @@ fn start_endpoint_workers(configs: &[AtofEndpointConfig]) -> Result Result Result { validate_endpoint_config(&config)?; let timeout = Duration::from_millis(config.timeout_millis); + let transport = config.transport; let (tx, rx) = tokio::sync::mpsc::unbounded_channel(); std::thread::Builder::new() .name(format!("nemo-relay-atof-endpoint-{index}")) .spawn(move || run_endpoint_worker(index, config, rx)) .map_err(|error| AtofExporterError::InvalidEndpoint(error.to_string()))?; + log::info!( + target: "nemo_relay.observability", + event = "endpoint_started", + exporter = "atof", + endpoint_index = index, + transport = transport.as_str(); + "ATOF endpoint worker started" + ); + log::info!( + target: "nemo_relay.plugin", + event = "plugin_resource_access_pending", + plugin_kind = "observability", + resource_kind = "stream_endpoint", + resource_index = index, + permission = "write"; + "Plugin resource access will be validated on first use" + ); Ok(AtofEndpointWorker { sender: tx, timeout, + index, + transport, }) } @@ -752,8 +824,15 @@ fn run_endpoint_worker( .build() { Ok(runtime) => runtime, - Err(error) => { - eprintln!("nemo_relay: ATOF endpoint[{index}] runtime failed: {error}"); + Err(_) => { + log::error!( + target: "nemo_relay.observability", + event = "endpoint_failed", + exporter = "atof", + endpoint_index = index, + reason = "runtime_initialization"; + "ATOF endpoint runtime failed" + ); return; } }; @@ -777,8 +856,16 @@ async fn run_http_post_endpoint( .default_headers( match resolved_header_map(&config.headers, &config.header_env) { Ok(headers) => headers, - Err(error) => { - eprintln!("nemo_relay: ATOF endpoint[{index}] disabled: {error}"); + Err(_) => { + log::error!( + target: "nemo_relay.observability", + event = "endpoint_disabled", + exporter = "atof", + endpoint_index = index, + transport = "http_post", + reason = "invalid_headers"; + "ATOF endpoint disabled" + ); drain_closed(rx).await; return; } @@ -787,12 +874,21 @@ async fn run_http_post_endpoint( .build() { Ok(client) => client, - Err(error) => { - eprintln!("nemo_relay: ATOF endpoint[{index}] client build failed: {error}"); + Err(_) => { + log::error!( + target: "nemo_relay.observability", + event = "endpoint_disabled", + exporter = "atof", + endpoint_index = index, + transport = "http_post", + reason = "client_initialization"; + "ATOF endpoint disabled" + ); drain_closed(rx).await; return; } }; + let mut access_validated = false; while let Some(message) = rx.recv().await { match message { EndpointMessage::Event(raw_json) => { @@ -804,11 +900,31 @@ async fn run_http_post_endpoint( .send() .await; match result { - Ok(response) if response.status().is_success() => {} - Ok(response) => log_http_error(index, "HTTP", response).await, - Err(error) => { - eprintln!("nemo_relay: ATOF endpoint[{index}] send failed: {error}") + Ok(response) if response.status().is_success() => { + if !access_validated { + log::info!( + target: "nemo_relay.observability", + event = "endpoint_access_validated", + plugin_kind = "observability", + exporter = "atof", + endpoint_index = index, + transport = "http_post", + permission = "write"; + "ATOF endpoint access validated" + ); + access_validated = true; + } } + Ok(response) => log_http_error(index, "http_post", response), + Err(_) => log::warn!( + target: "nemo_relay.observability", + event = "endpoint_delivery_failed", + exporter = "atof", + endpoint_index = index, + transport = "http_post", + reason = "request_failed"; + "ATOF endpoint delivery failed" + ), } } EndpointMessage::Flush(done) => { @@ -829,10 +945,14 @@ async fn run_websocket_endpoint( mut rx: tokio::sync::mpsc::UnboundedReceiver, ) { let mut pending = std::collections::VecDeque::new(); + let mut retry = WebSocketRetryState::default(); let mut socket = match connect_websocket(&config).await { - Ok(socket) => Some(socket), - Err(error) => { - eprintln!("nemo_relay: ATOF endpoint[{index}] websocket startup failed: {error}"); + Ok(socket) => { + retry.record_recovered(index); + Some(socket) + } + Err(_) => { + retry.record_failure(index); None } }; @@ -840,14 +960,20 @@ async fn run_websocket_endpoint( match message { EndpointMessage::Event(raw_json) => { pending.push_back(endpoint_event_json(&config, raw_json)); - let _ = drain_websocket_pending(index, &config, &mut socket, &mut pending).await; + let _ = + drain_websocket_pending(index, &config, &mut socket, &mut pending, &mut retry) + .await; } EndpointMessage::Flush(done) => { - let _ = drain_websocket_pending(index, &config, &mut socket, &mut pending).await; + let _ = + drain_websocket_pending(index, &config, &mut socket, &mut pending, &mut retry) + .await; let _ = done.send(()); } EndpointMessage::Close(done) => { - let _ = drain_websocket_pending(index, &config, &mut socket, &mut pending).await; + let _ = + drain_websocket_pending(index, &config, &mut socket, &mut pending, &mut retry) + .await; if let Some(mut ws) = socket.take() { let _ = ws.close(None).await; } @@ -862,23 +988,82 @@ async fn run_websocket_endpoint( type AtofWebSocket = tokio_tungstenite::WebSocketStream>; +#[cfg(feature = "atof-streaming")] +#[derive(Default)] +struct WebSocketRetryState { + attempts: u64, + warning_emitted: bool, + access_validated: bool, +} + +#[cfg(feature = "atof-streaming")] +impl WebSocketRetryState { + fn record_failure(&mut self, index: usize) { + self.attempts = self.attempts.saturating_add(1); + if !self.warning_emitted { + log::warn!( + target: "nemo_relay.observability", + event = "endpoint_reconnecting", + exporter = "atof", + endpoint_index = index, + transport = "websocket"; + "ATOF endpoint connection failed; reconnecting" + ); + self.warning_emitted = true; + } + } + + fn record_recovered(&mut self, index: usize) { + if self.attempts > 0 { + log::info!( + target: "nemo_relay.observability", + event = "endpoint_reconnected", + exporter = "atof", + endpoint_index = index, + transport = "websocket", + attempt_count = self.attempts + 1; + "ATOF endpoint reconnected" + ); + } + if !self.access_validated { + log::info!( + target: "nemo_relay.observability", + event = "endpoint_access_validated", + plugin_kind = "observability", + exporter = "atof", + endpoint_index = index, + transport = "websocket", + permission = "connect"; + "ATOF endpoint access validated" + ); + self.access_validated = true; + } + self.attempts = 0; + self.warning_emitted = false; + } +} + #[cfg(feature = "atof-streaming")] async fn drain_websocket_pending( index: usize, config: &AtofEndpointConfig, socket: &mut Option, pending: &mut std::collections::VecDeque, + retry: &mut WebSocketRetryState, ) -> bool { let timeout = Duration::from_millis(config.timeout_millis); + let attempts_before = retry.attempts; match tokio::time::timeout( timeout, - drain_websocket_pending_inner(index, config, socket, pending), + drain_websocket_pending_inner(index, config, socket, pending, retry), ) .await { Ok(drained) => drained, Err(_) => { - eprintln!("nemo_relay: ATOF endpoint[{index}] websocket drain timed out"); + if retry.attempts == attempts_before { + retry.record_failure(index); + } false } } @@ -890,15 +1075,17 @@ async fn drain_websocket_pending_inner( config: &AtofEndpointConfig, socket: &mut Option, pending: &mut std::collections::VecDeque, + retry: &mut WebSocketRetryState, ) -> bool { while let Some(raw_json) = pending.front().cloned() { if socket.is_none() { match connect_websocket(config).await { - Ok(ws) => *socket = Some(ws), - Err(error) => { - eprintln!( - "nemo_relay: ATOF endpoint[{index}] websocket reconnect failed: {error}" - ); + Ok(ws) => { + *socket = Some(ws); + retry.record_recovered(index); + } + Err(_) => { + retry.record_failure(index); tokio::time::sleep(Duration::from_millis(50)).await; continue; } @@ -917,8 +1104,8 @@ async fn drain_websocket_pending_inner( Ok(()) => { pending.pop_front(); } - Err(error) => { - eprintln!("nemo_relay: ATOF endpoint[{index}] websocket send failed: {error}"); + Err(_) => { + retry.record_failure(index); *socket = None; tokio::time::sleep(Duration::from_millis(50)).await; } @@ -962,8 +1149,16 @@ async fn run_ndjson_endpoint( ) { let client = match build_ndjson_client(&config) { Ok(client) => client, - Err(error) => { - eprintln!("nemo_relay: ATOF endpoint[{index}] {error}"); + Err(_) => { + log::error!( + target: "nemo_relay.observability", + event = "endpoint_disabled", + exporter = "atof", + endpoint_index = index, + transport = "ndjson", + reason = "client_initialization"; + "ATOF endpoint disabled" + ); drain_closed(rx).await; return; } @@ -1036,10 +1231,21 @@ fn send_ndjson_event( body_tx: &tokio::sync::mpsc::UnboundedSender, raw_json: String, ) { - if let Err(error) = body_tx.send(NdjsonBodyMessage::Event( - format!("{raw_json}\n").into_bytes(), - )) { - eprintln!("nemo_relay: ATOF endpoint[{index}] NDJSON send failed: {error}"); + if body_tx + .send(NdjsonBodyMessage::Event( + format!("{raw_json}\n").into_bytes(), + )) + .is_err() + { + log::warn!( + target: "nemo_relay.observability", + event = "endpoint_delivery_failed", + exporter = "atof", + endpoint_index = index, + transport = "ndjson", + reason = "body_channel_closed"; + "ATOF endpoint delivery failed" + ); } } @@ -1050,7 +1256,15 @@ fn send_ndjson_flush( done: std_mpsc::Sender<()>, ) { if let Err(error) = body_tx.send(NdjsonBodyMessage::Flush(done)) { - eprintln!("nemo_relay: ATOF endpoint[{index}] NDJSON flush failed: {error}"); + log::warn!( + target: "nemo_relay.observability", + event = "endpoint_flush_failed", + exporter = "atof", + endpoint_index = index, + transport = "ndjson", + reason = "body_channel_closed"; + "ATOF endpoint flush failed" + ); error.0.acknowledge_if_flush(); } } @@ -1063,15 +1277,44 @@ async fn finish_ndjson_upload( done: std_mpsc::Sender<()>, ) { match tokio::time::timeout(close_timeout, request).await { - Ok(Ok(Ok(response))) if response.status().is_success() => {} - Ok(Ok(Ok(response))) => log_http_error(index, "NDJSON HTTP", response).await, - Ok(Ok(Err(error))) => { - eprintln!("nemo_relay: ATOF endpoint[{index}] NDJSON upload failed: {error}") - } - Ok(Err(error)) => { - eprintln!("nemo_relay: ATOF endpoint[{index}] NDJSON task failed: {error}") - } - Err(_) => eprintln!("nemo_relay: ATOF endpoint[{index}] NDJSON close timed out"), + Ok(Ok(Ok(response))) if response.status().is_success() => log::info!( + target: "nemo_relay.observability", + event = "endpoint_access_validated", + plugin_kind = "observability", + exporter = "atof", + endpoint_index = index, + transport = "ndjson", + permission = "write"; + "ATOF endpoint access validated" + ), + Ok(Ok(Ok(response))) => log_http_error(index, "ndjson", response), + Ok(Ok(Err(_))) => log::warn!( + target: "nemo_relay.observability", + event = "endpoint_delivery_failed", + exporter = "atof", + endpoint_index = index, + transport = "ndjson", + reason = "upload_failed"; + "ATOF endpoint upload failed" + ), + Ok(Err(_)) => log::error!( + target: "nemo_relay.observability", + event = "endpoint_failed", + exporter = "atof", + endpoint_index = index, + transport = "ndjson", + reason = "task_failed"; + "ATOF endpoint task failed" + ), + Err(_) => log::warn!( + target: "nemo_relay.observability", + event = "endpoint_close_failed", + exporter = "atof", + endpoint_index = index, + transport = "ndjson", + reason = "timeout"; + "ATOF endpoint close timed out" + ), } let _ = done.send(()); } @@ -1155,30 +1398,17 @@ fn collision_free_key(object: &serde_json::Map, key: String) -> St } #[cfg(feature = "atof-streaming")] -async fn log_http_error(index: usize, label: &str, response: reqwest::Response) { +fn log_http_error(index: usize, transport: &str, response: reqwest::Response) { let status = response.status(); - match response.text().await { - Ok(body) if !body.trim().is_empty() => eprintln!( - "nemo_relay: ATOF endpoint[{index}] {label} status {status}: {}", - truncate_log_body(&body) - ), - Ok(_) => eprintln!("nemo_relay: ATOF endpoint[{index}] {label} status {status}"), - Err(error) => eprintln!( - "nemo_relay: ATOF endpoint[{index}] {label} status {status}; failed to read response body: {error}" - ), - } -} - -#[cfg(feature = "atof-streaming")] -fn truncate_log_body(body: &str) -> String { - const LIMIT: usize = 1024; - let trimmed = body.trim(); - if trimmed.chars().count() <= LIMIT { - return trimmed.to_string(); - } - let mut truncated = trimmed.chars().take(LIMIT).collect::(); - truncated.push_str("... "); - truncated + log::warn!( + target: "nemo_relay.observability", + event = "endpoint_delivery_failed", + exporter = "atof", + endpoint_index = index, + transport = transport, + status = status.as_u16(); + "ATOF endpoint returned an unsuccessful status" + ); } // --------------------------------------------------------------------------- diff --git a/crates/core/src/observability/mod.rs b/crates/core/src/observability/mod.rs index 128379fad..b55db2253 100644 --- a/crates/core/src/observability/mod.rs +++ b/crates/core/src/observability/mod.rs @@ -562,8 +562,13 @@ where .to_string(), ), "UNSET" => opentelemetry::trace::Status::Unset, - other => { - eprintln!("Unrecognized OTEL status code in event metadata: {other}"); + _ => { + log::warn!( + target: "nemo_relay.observability", + event = "invalid_status_code", + status_code = "invalid"; + "Unrecognized OpenTelemetry status code; using unset status" + ); opentelemetry::trace::Status::Unset } }; diff --git a/crates/core/src/observability/openinference.rs b/crates/core/src/observability/openinference.rs index b8cc19ae6..8b658d9e7 100644 --- a/crates/core/src/observability/openinference.rs +++ b/crates/core/src/observability/openinference.rs @@ -416,12 +416,29 @@ impl OpenInferenceSubscriber { /// Registers this subscriber globally with the NeMo Relay runtime. pub fn register(&self, name: &str) -> Result<()> { - register_subscriber(name, self.subscriber()).map_err(Into::into) + register_subscriber(name, self.subscriber())?; + log::info!( + target: "nemo_relay.observability", + event = "exporter_registered", + exporter = "openinference", + subscriber = name; + "OpenInference exporter registered" + ); + Ok(()) } /// Deregisters a previously-registered global subscriber by name. pub fn deregister(&self, name: &str) -> Result { - deregister_subscriber(name).map_err(Into::into) + let removed = deregister_subscriber(name)?; + if removed { + log::info!( + target: "nemo_relay.observability", + event = "subscriber_deregistered", + subscriber = name; + "Observability subscriber deregistered" + ); + } + Ok(removed) } /// Flushes finished spans through the underlying tracer provider. @@ -441,7 +458,16 @@ impl OpenInferenceSubscriber { let guard = self.inner.processor.lock().map_err(|_| { OpenInferenceError::Provider("the subscriber state lock was poisoned".to_string()) })?; - guard.shutdown() + let result = guard.shutdown(); + if result.is_ok() { + log::info!( + target: "nemo_relay.observability", + event = "exporter_shutdown", + exporter = "openinference"; + "OpenInference exporter shut down" + ); + } + result } } diff --git a/crates/core/src/observability/otel.rs b/crates/core/src/observability/otel.rs index 9b3e8c929..5fab7868a 100644 --- a/crates/core/src/observability/otel.rs +++ b/crates/core/src/observability/otel.rs @@ -410,12 +410,29 @@ impl OpenTelemetrySubscriber { /// Registers this subscriber globally with the NeMo Relay runtime. pub fn register(&self, name: &str) -> Result<()> { - register_subscriber(name, self.subscriber()).map_err(Into::into) + register_subscriber(name, self.subscriber())?; + log::info!( + target: "nemo_relay.observability", + event = "exporter_registered", + exporter = "opentelemetry", + subscriber = name; + "OpenTelemetry exporter registered" + ); + Ok(()) } /// Deregisters a previously-registered global subscriber by name. pub fn deregister(&self, name: &str) -> Result { - deregister_subscriber(name).map_err(Into::into) + let removed = deregister_subscriber(name)?; + if removed { + log::info!( + target: "nemo_relay.observability", + event = "subscriber_deregistered", + subscriber = name; + "Observability subscriber deregistered" + ); + } + Ok(removed) } /// Flushes finished spans through the underlying tracer provider. @@ -435,7 +452,16 @@ impl OpenTelemetrySubscriber { let guard = self.inner.processor.lock().map_err(|_| { OpenTelemetryError::Provider("the subscriber state lock was poisoned".to_string()) })?; - guard.shutdown() + let result = guard.shutdown(); + if result.is_ok() { + log::info!( + target: "nemo_relay.observability", + event = "exporter_shutdown", + exporter = "opentelemetry"; + "OpenTelemetry exporter shut down" + ); + } + result } } diff --git a/crates/core/src/observability/plugin_component.rs b/crates/core/src/observability/plugin_component.rs index 1f6cdee86..8a52fb6e6 100644 --- a/crates/core/src/observability/plugin_component.rs +++ b/crates/core/src/observability/plugin_component.rs @@ -21,6 +21,8 @@ use std::collections::{HashMap, HashSet}; use std::future::Future; use std::path::PathBuf; use std::pin::Pin; +#[cfg(feature = "object-store")] +use std::sync::atomic::{AtomicU8, Ordering}; use std::sync::{Arc, Mutex}; #[cfg(any(feature = "otel", feature = "openinference", feature = "object-store"))] use std::time::Duration; @@ -908,9 +910,19 @@ fn build_atif_storage( index: usize, config: &AtifStorageConfig, ) -> PluginResult> { - AtifRemoteStorage::from_config(index, config) + let storage = AtifRemoteStorage::from_config(index, config) .map(Arc::new) - .map_err(observability_registration_error) + .map_err(observability_registration_error)?; + log::info!( + target: "nemo_relay.plugin", + event = "plugin_resource_access_pending", + plugin_kind = OBSERVABILITY_PLUGIN_KIND, + resource_kind = storage.resource_kind, + resource_index = index, + permission = "write"; + "Plugin resource access will be validated on first use" + ); + Ok(storage) } #[cfg(not(feature = "object-store"))] @@ -928,10 +940,22 @@ fn register_opentelemetry( section: OtlpSectionConfig, ctx: &mut PluginRegistrationContext, ) -> PluginResult<()> { + let endpoint_configured = section.endpoint.is_some(); let subscriber = Arc::new( OpenTelemetrySubscriber::new(build_otel_config(section)?) .map_err(observability_registration_error)?, ); + if endpoint_configured { + log::info!( + target: "nemo_relay.plugin", + event = "plugin_resource_access_pending", + plugin_kind = OBSERVABILITY_PLUGIN_KIND, + resource_kind = "otlp_endpoint", + exporter = "opentelemetry", + permission = "write"; + "Plugin resource access will be validated during export" + ); + } ctx.register_subscriber("opentelemetry", subscriber.subscriber())?; ctx.add_registration(PluginRegistration::new( "observability", @@ -960,10 +984,22 @@ fn register_openinference( section: OtlpSectionConfig, ctx: &mut PluginRegistrationContext, ) -> PluginResult<()> { + let endpoint_configured = section.endpoint.is_some(); let subscriber = Arc::new( OpenInferenceSubscriber::new(build_openinference_config(section)?) .map_err(observability_registration_error)?, ); + if endpoint_configured { + log::info!( + target: "nemo_relay.plugin", + event = "plugin_resource_access_pending", + plugin_kind = OBSERVABILITY_PLUGIN_KIND, + resource_kind = "otlp_endpoint", + exporter = "openinference", + permission = "write"; + "Plugin resource access will be validated during export" + ); + } ctx.register_subscriber("openinference", subscriber.subscriber())?; ctx.add_registration(PluginRegistration::new( "observability", @@ -999,6 +1035,7 @@ struct AtifDispatcher { /// Per-sink last error. A sink that recorded an error is skipped on /// subsequent trajectories; other sinks continue to receive writes. sink_errors: HashMap, + validated_sinks: HashSet, } struct ManagedAtifExporter { @@ -1098,6 +1135,7 @@ impl AtifDispatcher { scope_subscribers: HashMap::new(), fatal_error: None, sink_errors: HashMap::new(), + validated_sinks: HashSet::new(), } } @@ -1219,7 +1257,33 @@ impl AtifDispatcher { results: Vec<(SinkLabel, std::io::Result<()>)>, ) -> Option<(Uuid, String)> { for (label, result) in results { - if let Err(err) = result { + if result.is_ok() + && label == SinkLabel::Local + && self.validated_sinks.insert(label.clone()) + { + log::info!( + target: "nemo_relay.observability", + event = "storage_access_validated", + plugin_kind = "observability", + exporter = "atif", + resource_kind = "local_file", + permission = "write"; + "ATIF storage access validated" + ); + } else if let Err(err) = result { + match &label { + SinkLabel::Local => log::warn!( + target: "nemo_relay.observability", + event = "storage_access_failed", + plugin_kind = "observability", + exporter = "atif", + resource_kind = "local_file", + permission = "write", + reason = "write_failed"; + "ATIF storage access failed" + ), + SinkLabel::Remote(_) => {} + } self.sink_errors.insert(label, err.to_string()); } } @@ -2665,6 +2729,9 @@ struct AtifRemoteStorage; struct AtifRemoteStorage { sender: std::sync::mpsc::Sender, key_prefix: String, + index: usize, + resource_kind: &'static str, + access_state: AtomicU8, } #[cfg(feature = "object-store")] @@ -2827,6 +2894,9 @@ impl AtifRemoteStorage { Ok(Ok(())) => Ok(Self { sender: req_tx, key_prefix: String::new(), + index, + resource_kind: "http_endpoint", + access_state: AtomicU8::new(0), }), Ok(Err(err)) => Err(err), Err(_) => Err(std::io::Error::other( @@ -2904,6 +2974,9 @@ impl AtifRemoteStorage { Ok(Ok(())) => Ok(Self { sender: req_tx, key_prefix, + index, + resource_kind: "s3_bucket", + access_state: AtomicU8::new(0), }), Ok(Err(err)) => Err(err), Err(_) => Err(std::io::Error::other( @@ -2924,9 +2997,47 @@ impl AtifRemoteStorage { reply: reply_tx, }) .map_err(|_| std::io::Error::other("ATIF storage thread is not running"))?; - reply_rx - .recv() - .map_err(|_| std::io::Error::other("ATIF storage thread dropped the upload reply"))? + let (result, failure_reason) = match reply_rx.recv() { + Ok(result) => (result, "upload_failed"), + Err(_) => ( + Err(std::io::Error::other( + "ATIF storage thread dropped the upload reply", + )), + "reply_channel_closed", + ), + }; + match &result { + Ok(()) => { + if self.access_state.swap(2, Ordering::AcqRel) != 2 { + log::info!( + target: "nemo_relay.observability", + event = "storage_access_validated", + plugin_kind = "observability", + exporter = "atif", + resource_index = self.index, + resource_kind = self.resource_kind, + permission = "write"; + "ATIF storage access validated" + ); + } + } + Err(_) => { + if self.access_state.swap(1, Ordering::AcqRel) != 1 { + log::warn!( + target: "nemo_relay.observability", + event = "storage_access_failed", + plugin_kind = "observability", + exporter = "atif", + resource_index = self.index, + resource_kind = self.resource_kind, + permission = "write", + reason = failure_reason; + "ATIF storage access failed" + ); + } + } + } + result } } diff --git a/crates/core/src/plugin.rs b/crates/core/src/plugin.rs index e1f46ca0a..ab03b9c96 100644 --- a/crates/core/src/plugin.rs +++ b/crates/core/src/plugin.rs @@ -908,13 +908,20 @@ fn register_plugin_with_owner( } let registration_id = NEXT_PLUGIN_REGISTRATION_ID.fetch_add(1, Ordering::Relaxed); guard.insert( - plugin_kind, + plugin_kind.clone(), RegisteredPlugin { registration_id, owner, plugin, }, ); + log::info!( + target: "nemo_relay.plugin", + event = "plugin_registered", + plugin_kind = plugin_kind.as_str(), + registration_id = registration_id; + "Plugin kind registered" + ); Ok(registration_id) } @@ -971,10 +978,19 @@ pub fn deregister_plugin(plugin_kind: &str) -> bool { } pub(crate) fn deregister_plugin_checked(plugin_kind: &str) -> Result { - PLUGIN_HANDLERS + let removed = PLUGIN_HANDLERS .write() .map(|mut guard| guard.remove(plugin_kind).is_some()) - .map_err(|err| PluginError::Internal(format!("plugin registry lock poisoned: {err}"))) + .map_err(|err| PluginError::Internal(format!("plugin registry lock poisoned: {err}")))?; + if removed { + log::info!( + target: "nemo_relay.plugin", + event = "plugin_deregistered", + plugin_kind = plugin_kind; + "Plugin kind deregistered" + ); + } + Ok(removed) } pub(crate) fn deregister_plugin_registration_checked( @@ -987,6 +1003,13 @@ pub(crate) fn deregister_plugin_registration_checked( match guard.get(plugin_kind) { Some(plugin) if plugin.registration_id == expected_registration_id => { guard.remove(plugin_kind); + log::info!( + target: "nemo_relay.plugin", + event = "plugin_deregistered", + plugin_kind = plugin_kind, + registration_id = expected_registration_id; + "Plugin kind deregistered" + ); Ok(PluginDeregistrationOutcome::Removed) } Some(_) => Ok(PluginDeregistrationOutcome::Replaced), @@ -1373,6 +1396,17 @@ async fn initialize_plugins_exact_inner( config: PluginConfig, rollback_failures: Option>>>, ) -> Result { + let enabled_component_count = config + .components + .iter() + .filter(|component| component.enabled) + .count(); + log::info!( + target: "nemo_relay.plugin", + event = "plugin_configuration_activation_started", + component_count = enabled_component_count; + "Plugin configuration activation started" + ); let report = validate_plugin_config(&config); if report.has_errors() { return Err(PluginError::InvalidConfig(join_error_messages(&report))); @@ -1402,6 +1436,12 @@ async fn initialize_plugins_exact_inner( { Ok(registrations) => { store_active_plugin_configuration(config, report.clone(), registrations)?; + log::info!( + target: "nemo_relay.plugin", + event = "plugin_configuration_replaced", + component_count = enabled_component_count; + "Plugin configuration replaced" + ); Ok(report) } Err(err) => match initialize_plugin_components_catching_panics( @@ -1417,17 +1457,37 @@ async fn initialize_plugins_exact_inner( previous_report, registrations, )?; + log::warn!( + target: "nemo_relay.plugin", + event = "plugin_configuration_restored", + recovery = "previous_configuration"; + "Plugin activation failed; previous configuration restored" + ); Err(err) } - Err(restore_err) => Err(PluginError::RegistrationFailed(format!( - "{err}; previous plugin configuration could not be restored: {restore_err}" - ))), + Err(restore_err) => { + log::error!( + target: "nemo_relay.plugin", + event = "plugin_rollback_failed", + recovery = "previous_configuration"; + "Plugin activation failed and the previous configuration could not be restored" + ); + Err(PluginError::RegistrationFailed(format!( + "{err}; previous plugin configuration could not be restored: {restore_err}" + ))) + } }, } } else { let registrations = initialize_plugin_components_catching_panics(config.clone(), rollback_failures).await?; store_active_plugin_configuration(config, report.clone(), registrations)?; + log::info!( + target: "nemo_relay.plugin", + event = "plugin_configuration_activated", + component_count = enabled_component_count; + "Plugin configuration activated" + ); Ok(report) } } @@ -1606,6 +1666,12 @@ pub fn clear_plugin_configuration() -> Result<()> { // Deregistration callbacks are single-use. If one failed, the process // can no longer prove that replacing configuration is safe. std::mem::forget(lease); + log::error!( + target: "nemo_relay.plugin", + event = "plugin_cleanup_failed", + callbacks_cleared = false; + "Plugin configuration cleanup was incomplete" + ); return Err(PluginError::RegistrationFailed(format!( concat!( "{}; plugin configuration mutations are disabled for this process because ", @@ -1618,6 +1684,13 @@ pub fn clear_plugin_configuration() -> Result<()> { .unwrap_or_else(|| "plugin teardown was incomplete".into()) ))); } + if outcome.result.is_ok() { + log::info!( + target: "nemo_relay.plugin", + event = "plugin_configuration_cleared"; + "Plugin configuration cleared" + ); + } outcome.result } diff --git a/crates/core/src/plugin/dynamic/host.rs b/crates/core/src/plugin/dynamic/host.rs index f3fa7f820..8b3f3e2df 100644 --- a/crates/core/src/plugin/dynamic/host.rs +++ b/crates/core/src/plugin/dynamic/host.rs @@ -115,6 +115,13 @@ impl PluginHostActivation { mut config: PluginConfig, dynamic_plugins: Vec, ) -> Result<(Self, ConfigReport)> { + let dynamic_plugin_count = dynamic_plugins.len(); + log::info!( + target: "nemo_relay.plugin", + event = "dynamic_plugin_activation_started", + plugin_count = dynamic_plugin_count; + "Dynamic plugin activation started" + ); let claim = acquire_plugin_host_lease()?; #[cfg(not(feature = "worker-grpc"))] @@ -202,6 +209,13 @@ impl PluginHostActivation { if failures.is_empty() { return Err(error); } + log::error!( + target: "nemo_relay.plugin", + event = "plugin_rollback_failed", + plugin_count = dynamic_plugin_count, + failure_count = failures.len(); + "Dynamic plugin activation rollback was incomplete" + ); if let Some(native) = native { std::mem::forget(native); } @@ -221,6 +235,12 @@ impl PluginHostActivation { } }; + log::info!( + target: "nemo_relay.plugin", + event = "dynamic_plugin_activated", + plugin_count = dynamic_plugin_count; + "Dynamic plugins activated" + ); Ok(( Self { active: true, @@ -307,6 +327,11 @@ impl PluginHostActivation { self.claim.take(); if errors.is_empty() { + log::info!( + target: "nemo_relay.plugin", + event = "dynamic_plugin_cleared"; + "Dynamic plugin activation cleared" + ); Ok(()) } else { Err(crate::plugin::PluginError::RegistrationFailed(format!( @@ -390,8 +415,13 @@ fn plugin_error_context( impl Drop for PluginHostActivation { fn drop(&mut self) { - if let Err(error) = self.clear_inner() { - eprintln!("nemo_relay: dynamic plugin activation cleanup failed during drop: {error}"); + if self.clear_inner().is_err() { + log::error!( + target: "nemo_relay.plugin", + event = "plugin_cleanup_failed", + cleanup = "dynamic_activation_drop"; + "Dynamic plugin activation cleanup failed during drop" + ); } } } diff --git a/crates/core/src/plugin/dynamic/worker.rs b/crates/core/src/plugin/dynamic/worker.rs index b326052d8..9183eaaa8 100644 --- a/crates/core/src/plugin/dynamic/worker.rs +++ b/crates/core/src/plugin/dynamic/worker.rs @@ -244,7 +244,17 @@ struct WorkerPluginInstance { impl Drop for WorkerPluginInstance { fn drop(&mut self) { - let _ = self.shutdown_checked(); + let outcome = self.shutdown_checked(); + if !outcome.errors.is_empty() { + log::error!( + target: "nemo_relay.worker", + event = "worker_cleanup_failed", + plugin_id = self.plugin_kind.as_str(), + failure_count = outcome.errors.len(), + safe_to_unload = outcome.safe_to_unload; + "Worker plugin cleanup failed during drop" + ); + } } } @@ -255,6 +265,13 @@ impl WorkerPluginInstance { return outcome; } + log::info!( + target: "nemo_relay.worker", + event = "worker_stopping", + plugin_id = self.plugin_kind.as_str(); + "Worker plugin is stopping" + ); + let mut client = self.client.clone(); let request = ShutdownRequest { activation_id: self.host_state.activation_id.clone(), @@ -321,6 +338,14 @@ impl WorkerPluginInstance { true, ); } + if outcome.errors.is_empty() { + log::info!( + target: "nemo_relay.worker", + event = "worker_stopped", + plugin_id = self.plugin_kind.as_str(); + "Worker plugin stopped" + ); + } outcome } @@ -403,6 +428,12 @@ fn panic_payload_message(payload: &(dyn std::any::Any + Send)) -> &str { fn load_one_worker_plugin( spec: &WorkerPluginLoadSpec, ) -> crate::plugin::Result> { + log::info!( + target: "nemo_relay.worker", + event = "worker_starting", + plugin_id = spec.plugin_id.as_str(); + "Worker plugin is starting" + ); let (manifest, manifest_ref) = DynamicPluginManifest::load_from_path(&spec.manifest_ref)?; if manifest.plugin.id.trim() != spec.plugin_id { return Err(PluginError::InvalidConfig(format!( @@ -473,9 +504,20 @@ fn load_one_worker_plugin( worker_endpoint: &worker_advertise, worker_endpoint_file: worker_endpoint_file.as_deref(), })?); + log::info!( + target: "nemo_relay.worker", + event = "worker_started", + plugin_id = spec.plugin_id.as_str(), + pid = child + .child + .as_ref() + .expect("worker child should remain guarded") + .id(); + "Worker plugin process started" + ); let mut client = block_on_runtime( runtime_handle.runtime(), - connect_worker_with_retry(&worker_connect), + connect_worker_with_retry(&worker_connect, &spec.plugin_id), )?; let health = block_on_runtime( @@ -565,6 +607,12 @@ fn load_one_worker_plugin( register.registrations }; + log::info!( + target: "nemo_relay.worker", + event = "worker_connected", + plugin_id = spec.plugin_id.as_str(); + "Worker plugin connected and registered" + ); Ok(Arc::new(WorkerPluginInstance { plugin_kind: spec.plugin_id.clone(), allows_multiple_components: handshake.allows_multiple_components, @@ -663,8 +711,13 @@ async fn serve_host_runtime( HostRuntimeServer::Unix(listener) => { let listener = match UnixListener::from_std(listener) { Ok(listener) => listener, - Err(err) => { - eprintln!("failed to attach worker host runtime socket: {err}"); + Err(_) => { + log::error!( + target: "nemo_relay.worker", + event = "worker_host_runtime_failed", + transport = "unix"; + "Worker host runtime failed to attach its socket" + ); return; } }; @@ -679,8 +732,13 @@ async fn serve_host_runtime( HostRuntimeServer::Tcp(listener) => { let listener = match TokioTcpListener::from_std(listener) { Ok(listener) => listener, - Err(err) => { - eprintln!("failed to attach worker host runtime endpoint: {err}"); + Err(_) => { + log::error!( + target: "nemo_relay.worker", + event = "worker_host_runtime_failed", + transport = "tcp"; + "Worker host runtime failed to attach its endpoint" + ); return; } }; @@ -692,15 +750,23 @@ async fn serve_host_runtime( .await } }; - if let Err(err) = result { - eprintln!("worker host runtime server failed: {err}"); + if result.is_err() { + log::error!( + target: "nemo_relay.worker", + event = "worker_host_runtime_failed", + reason = "server_stopped"; + "Worker host runtime server failed" + ); } } async fn connect_worker_with_retry( endpoint: &WorkerConnectEndpoint, + plugin_id: &str, ) -> crate::plugin::Result> { let start = std::time::Instant::now(); + let mut attempts = 0_u64; + let mut retry_logged = false; loop { let connect_endpoint = match resolve_worker_connect_endpoint(endpoint) { Ok(Some(endpoint)) => endpoint, @@ -718,9 +784,29 @@ async fn connect_worker_with_retry( Err(err) => return Err(err), }; match connect_worker(&connect_endpoint).await { - Ok(client) => return Ok(client), - Err(err) if start.elapsed() < WORKER_STARTUP_TIMEOUT => { - let _ = err; + Ok(client) => { + if attempts > 0 { + log::info!( + target: "nemo_relay.worker", + event = "worker_connection_recovered", + plugin_id = plugin_id, + attempt_count = attempts + 1; + "Worker plugin connection recovered" + ); + } + return Ok(client); + } + Err(_) if start.elapsed() < WORKER_STARTUP_TIMEOUT => { + attempts = attempts.saturating_add(1); + if !retry_logged { + log::warn!( + target: "nemo_relay.worker", + event = "worker_connection_retrying", + plugin_id = plugin_id; + "Worker plugin connection failed; retrying" + ); + retry_logged = true; + } tokio::time::sleep(WORKER_CONNECT_RETRY).await; } Err(err) => { @@ -960,7 +1046,12 @@ impl WorkerPluginInstance { ctx.register_subscriber( &name, Arc::new(move |event| { - let _ = instance.invoke_subscriber(&callback_name, event); + if instance.invoke_subscriber(&callback_name, event).is_err() { + instance.log_callback_fallback( + &callback_name, + RegistrationSurface::Subscriber, + ); + } }), )?; } @@ -972,7 +1063,10 @@ impl WorkerPluginInstance { let callback = Arc::new(move |event: &Event, fields: EventSanitizeFields| { instance .invoke_event_sanitize(&callback_name, surface, event) - .unwrap_or(fields) + .unwrap_or_else(|_| { + instance.log_callback_fallback(&callback_name, surface); + fields + }) }); match surface { RegistrationSurface::MarkSanitizeGuardrail => { @@ -1002,7 +1096,13 @@ impl WorkerPluginInstance { value.clone(), None, ) - .unwrap_or(value) + .unwrap_or_else(|_| { + instance.log_callback_fallback( + &callback_name, + RegistrationSurface::ToolSanitizeRequestGuardrail, + ); + value + }) }), )?; } @@ -1021,7 +1121,13 @@ impl WorkerPluginInstance { value.clone(), None, ) - .unwrap_or(value) + .unwrap_or_else(|_| { + instance.log_callback_fallback( + &callback_name, + RegistrationSurface::ToolSanitizeResponseGuardrail, + ); + value + }) }), )?; } @@ -1088,7 +1194,13 @@ impl WorkerPluginInstance { None, None, ) - .unwrap_or(request) + .unwrap_or_else(|_| { + instance.log_callback_fallback( + &callback_name, + RegistrationSurface::LlmSanitizeRequestGuardrail, + ); + request + }) }), )?; } @@ -1106,7 +1218,13 @@ impl WorkerPluginInstance { "", value.clone(), ) - .unwrap_or(value) + .unwrap_or_else(|_| { + instance.log_callback_fallback( + &callback_name, + RegistrationSurface::LlmSanitizeResponseGuardrail, + ); + value + }) }), )?; } @@ -1187,6 +1305,7 @@ impl WorkerPluginInstance { fn clone_for_callback(&self) -> WorkerPluginCallback { WorkerPluginCallback { + plugin_kind: self.plugin_kind.clone(), activation_id: self.host_state.activation_id.clone(), runtime: self.runtime.handle(), client: self.client.clone(), @@ -1217,12 +1336,26 @@ fn bind_loopback_listener() -> crate::plugin::Result<(TcpListener, SocketAddr)> #[derive(Clone)] struct WorkerPluginCallback { + plugin_kind: String, activation_id: String, runtime: tokio::runtime::Handle, client: PluginWorkerClient, host_state: Arc, } +impl WorkerPluginCallback { + fn log_callback_fallback(&self, callback_name: &str, surface: RegistrationSurface) { + log::warn!( + target: "nemo_relay.worker", + event = "worker_callback_fallback", + plugin_id = self.plugin_kind.as_str(), + callback = callback_name, + surface = surface.as_str_name(); + "Worker plugin callback failed; Relay used the safe fallback" + ); + } +} + struct WorkerInvocationGuard { runtime: tokio::runtime::Handle, client: PluginWorkerClient, diff --git a/crates/core/src/plugins/model_pricing.rs b/crates/core/src/plugins/model_pricing.rs index ae1862a98..98963b7a5 100644 --- a/crates/core/src/plugins/model_pricing.rs +++ b/crates/core/src/plugins/model_pricing.rs @@ -74,6 +74,13 @@ impl Plugin for PricingPlugin { .map_err(|error| PluginError::InvalidConfig(error.to_string()))?; set_active_pricing_resolver(resolver) .map_err(|error| PluginError::RegistrationFailed(error.to_string()))?; + log::info!( + target: "nemo_relay.plugin", + event = "plugin_resource_validation_completed", + plugin_kind = PRICING_PLUGIN_KIND, + resource_count = 0; + "Plugin resource validation completed" + ); ctx.add_registration(PluginRegistration::new( "plugin", ctx.qualify_name("pricing"), diff --git a/crates/core/src/plugins/nemo_guardrails/python.rs b/crates/core/src/plugins/nemo_guardrails/python.rs index 63784d102..485467ba2 100644 --- a/crates/core/src/plugins/nemo_guardrails/python.rs +++ b/crates/core/src/plugins/nemo_guardrails/python.rs @@ -6,7 +6,7 @@ use std::env; use std::ffi::{OsStr, OsString}; use std::io::{BufRead, BufReader, Write}; use std::process::{Child, ChildStdin, ChildStdout, Command, Stdio}; -use std::sync::atomic::{AtomicU64, Ordering}; +use std::sync::atomic::{AtomicBool, AtomicU64, Ordering}; use std::sync::{Arc, Mutex, mpsc as std_mpsc}; use std::thread; use std::time::Duration; @@ -368,10 +368,17 @@ struct LocalGuardrailsWorker { waiters: Arc>>>, stream_events: Arc>>>, next_id: AtomicU64, + shutdown_started: AtomicBool, } impl LocalGuardrailsWorker { fn start(config: &NeMoGuardrailsConfig) -> PluginResult> { + log::info!( + target: "nemo_relay.worker", + event = "worker_starting", + plugin_id = "nemo_guardrails"; + "NeMo Guardrails local worker is starting" + ); let python = python_executable(config); let mut command = Command::new(&python); command @@ -407,9 +414,24 @@ impl LocalGuardrailsWorker { waiters: Arc::new(Mutex::new(HashMap::new())), stream_events: Arc::new(Mutex::new(HashMap::new())), next_id: AtomicU64::new(1), + shutdown_started: AtomicBool::new(false), }); worker.spawn_reader(stdout); worker.initialize(config)?; + log::info!( + target: "nemo_relay.plugin", + event = "plugin_resource_access_validated", + plugin_kind = "nemo_guardrails", + resource_kind = "python_worker", + permission = "execute"; + "Plugin resource access validated" + ); + log::info!( + target: "nemo_relay.worker", + event = "worker_connected", + plugin_id = "nemo_guardrails"; + "NeMo Guardrails local worker connected" + ); Ok(worker) } @@ -467,20 +489,31 @@ impl LocalGuardrailsWorker { } } - async fn request(&self, mut payload: Json) -> FlowResult { + async fn request(&self, payload: Json) -> FlowResult { + self.request_with_timeout(payload, WORKER_RPC_TIMEOUT).await + } + + async fn request_with_timeout(&self, mut payload: Json, timeout: Duration) -> FlowResult { let receiver = self.send_request(&mut payload)?; let response_task = tokio::task::spawn_blocking(move || receiver.recv()); - let envelope = match tokio::time::timeout(WORKER_RPC_TIMEOUT, response_task).await { + let envelope = match tokio::time::timeout(timeout, response_task).await { Ok(result) => result .map_err(|err| FlowError::Internal(format!("worker response task failed: {err}")))? .map_err(|err| { FlowError::Internal(format!("worker response channel closed: {err}")) })?, Err(_) => { + log::error!( + target: "nemo_relay.worker", + event = "worker_failed", + plugin_id = "nemo_guardrails", + reason = "request_timeout"; + "NeMo Guardrails local worker request timed out" + ); self.shutdown(); return Err(FlowError::Internal(format!( "worker request timed out after {} seconds", - WORKER_RPC_TIMEOUT.as_secs() + timeout.as_secs() ))); } }; @@ -572,14 +605,50 @@ impl LocalGuardrailsWorker { } fn shutdown(&self) { + if self.shutdown_started.swap(true, Ordering::AcqRel) { + return; + } + log::info!( + target: "nemo_relay.worker", + event = "worker_stopping", + plugin_id = "nemo_guardrails"; + "NeMo Guardrails local worker is stopping" + ); let writer = self.writer.lock().ok().and_then(|mut writer| writer.take()); + let mut cleanup_succeeded = true; if let Ok(mut child) = self.child.lock() { - let _ = child.kill(); - let _ = child.wait(); + if child.kill().is_err() { + cleanup_succeeded = false; + log::warn!( + target: "nemo_relay.worker", + event = "worker_cleanup_failed", + plugin_id = "nemo_guardrails", + operation = "kill"; + "NeMo Guardrails local worker cleanup failed" + ); + } + if child.wait().is_err() { + cleanup_succeeded = false; + log::warn!( + target: "nemo_relay.worker", + event = "worker_cleanup_failed", + plugin_id = "nemo_guardrails", + operation = "wait"; + "NeMo Guardrails local worker cleanup failed" + ); + } } if let Some(writer) = writer { writer.join(); } + if cleanup_succeeded { + log::info!( + target: "nemo_relay.worker", + event = "worker_stopped", + plugin_id = "nemo_guardrails"; + "NeMo Guardrails local worker stopped" + ); + } } } diff --git a/crates/core/src/plugins/nemo_guardrails/remote.rs b/crates/core/src/plugins/nemo_guardrails/remote.rs index 7e3bce374..2ed41dd0a 100644 --- a/crates/core/src/plugins/nemo_guardrails/remote.rs +++ b/crates/core/src/plugins/nemo_guardrails/remote.rs @@ -2,6 +2,7 @@ // SPDX-License-Identifier: Apache-2.0 use std::sync::Arc; +use std::sync::atomic::{AtomicU8, Ordering}; use std::time::Duration; use serde_json::{Map, Value as Json, json}; @@ -29,6 +30,7 @@ struct RemoteBackendRuntime { llm_guardrails: Option>, tool_input_guardrails: Map, tool_output_guardrails: Map, + access_state: Arc, } #[derive(Clone, Copy)] @@ -74,6 +76,15 @@ impl RemoteBackendRuntime { let request_defaults = config.request_defaults.as_ref(); + log::info!( + target: "nemo_relay.plugin", + event = "plugin_resource_access_pending", + plugin_kind = "nemo_guardrails", + resource_kind = "http_endpoint", + permission = "invoke"; + "Plugin resource access will be validated on first use" + ); + Ok(Self { endpoint: endpoint.trim_end_matches('/').to_string(), client, @@ -98,6 +109,7 @@ impl RemoteBackendRuntime { &remote.config_ids, request_defaults, ), + access_state: Arc::new(AtomicU8::new(0)), }) } @@ -219,21 +231,79 @@ impl RemoteBackendRuntime { body: Json, ) -> crate::error::Result { let serialized = self.serialize_request_body_with_marks(parent, stream, body)?; - self.client + match self + .client .post(self.chat_completions_url()) .header(reqwest::header::CONTENT_TYPE, "application/json") .body(serialized) .send() .await - .map_err(|err| { + { + Ok(response) => { + self.record_access_status(response.status()); + Ok(response) + } + Err(err) => { + self.record_access_failure("connection_failed", None); let message = if stream { format!("remote stream request failed: {err}") } else { format!("remote request failed: {err}") }; self.emit_remote_error(parent, stream, None, message.clone()); - FlowError::Internal(format!("nemo_guardrails {message}")) - }) + Err(FlowError::Internal(format!("nemo_guardrails {message}"))) + } + } + } + + fn record_access_status(&self, status: reqwest::StatusCode) { + if status.is_success() { + if self.access_state.swap(2, Ordering::AcqRel) != 2 { + log::info!( + target: "nemo_relay.plugin", + event = "plugin_resource_access_validated", + plugin_kind = "nemo_guardrails", + resource_kind = "http_endpoint", + permission = "invoke", + status_code = status.as_u16(); + "Plugin resource access validated" + ); + } + return; + } + let reason = if matches!(status.as_u16(), 401 | 403) { + "permission_denied" + } else { + "unsuccessful_status" + }; + self.record_access_failure(reason, Some(status.as_u16())); + } + + fn record_access_failure(&self, reason: &'static str, status_code: Option) { + if self.access_state.swap(1, Ordering::AcqRel) == 1 { + return; + } + match status_code { + Some(status_code) => log::warn!( + target: "nemo_relay.plugin", + event = "plugin_resource_access_failed", + plugin_kind = "nemo_guardrails", + resource_kind = "http_endpoint", + permission = "invoke", + reason = reason, + status_code = status_code; + "Plugin resource access validation failed" + ), + None => log::warn!( + target: "nemo_relay.plugin", + event = "plugin_resource_access_failed", + plugin_kind = "nemo_guardrails", + resource_kind = "http_endpoint", + permission = "invoke", + reason = reason; + "Plugin resource access validation failed" + ), + } } fn serialize_request_body_with_marks( @@ -492,14 +562,20 @@ impl RemoteBackendRuntime { ); FlowError::Internal(message) })?; - let response = self + let response = match self .client .post(self.chat_completions_url()) .header(reqwest::header::CONTENT_TYPE, "application/json") .body(serialized) .send() .await - .map_err(|err| { + { + Ok(response) => { + self.record_access_status(response.status()); + response + } + Err(err) => { + self.record_access_failure("connection_failed", None); let message = format!("nemo_guardrails remote request failed: {err}"); self.emit_mark( "nemo_guardrails.remote.error", @@ -513,8 +589,9 @@ impl RemoteBackendRuntime { Some(message.clone()), ), ); - FlowError::Internal(message) - })?; + return Err(FlowError::Internal(message)); + } + }; let status = response.status(); let payload = response.text().await.map_err(|err| { let message = format!("nemo_guardrails failed to read remote response body: {err}"); diff --git a/crates/core/src/shared_runtime.rs b/crates/core/src/shared_runtime.rs index c1cf44722..23f956c15 100644 --- a/crates/core/src/shared_runtime.rs +++ b/crates/core/src/shared_runtime.rs @@ -207,6 +207,13 @@ pub(crate) fn ensure_process_runtime_owner() -> Result<()> { Some(existing) if existing.same_owner(¤t) => Ok(()), Some(existing) if existing.pid != current.pid => { publish_process_runtime_owner(¤t); + log::info!( + target: "nemo_relay.runtime", + event = "runtime_owner_claimed", + binding = current.binding_kind.as_str(), + pid = current.pid; + "Relay runtime ownership claimed" + ); Ok(()) } Some(existing) => Err(FlowError::InvalidArgument(format!( @@ -215,6 +222,13 @@ pub(crate) fn ensure_process_runtime_owner() -> Result<()> { ))), None => { publish_process_runtime_owner(¤t); + log::info!( + target: "nemo_relay.runtime", + event = "runtime_owner_claimed", + binding = current.binding_kind.as_str(), + pid = current.pid; + "Relay runtime ownership claimed" + ); Ok(()) } } diff --git a/crates/core/tests/coverage/logging_sink_tests.rs b/crates/core/tests/coverage/logging_sink_tests.rs index f235d7313..044ce2b47 100644 --- a/crates/core/tests/coverage/logging_sink_tests.rs +++ b/crates/core/tests/coverage/logging_sink_tests.rs @@ -1,7 +1,11 @@ // SPDX-FileCopyrightText: Copyright (c) 2026, NVIDIA CORPORATION & AFFILIATES. All rights reserved. // SPDX-License-Identifier: Apache-2.0 -use super::{DROP_REPORT_INTERVAL_MILLIS, DropNoticeRateLimiter}; +use super::{ + DROP_REPORT_INTERVAL_MILLIS, DropNoticeRateLimiter, dropped_record_error_handler, + log_level_filter, now_millis, spdlog_level, stderr_error_handler, +}; +use crate::logging::LogLevel; #[test] fn drop_notice_rate_limiter_reports_immediately_then_once_per_interval() { @@ -13,3 +17,19 @@ fn drop_notice_rate_limiter_reports_immediately_then_once_per_interval() { assert!(!rate_limiter.should_report(first_timestamp + interval - 1)); assert!(rate_limiter.should_report(first_timestamp + interval)); } + +#[test] +fn sink_helpers_cover_boundary_levels_time_and_emergency_handlers() { + assert_eq!(spdlog_level(LogLevel::Error), spdlog::Level::Error); + assert_eq!(spdlog_level(LogLevel::Trace), spdlog::Level::Trace); + assert_eq!(log_level_filter(LogLevel::Error), log::LevelFilter::Error); + assert_eq!(log_level_filter(LogLevel::Trace), log::LevelFilter::Trace); + assert!(now_millis() > 0); + + stderr_error_handler("test")(spdlog::Error::WriteRecord(std::io::Error::other( + "expected test error", + ))); + dropped_record_error_handler("test")(spdlog::Error::WriteRecord(std::io::Error::other( + "expected test error", + ))); +} diff --git a/crates/core/tests/coverage/logging_tests.rs b/crates/core/tests/coverage/logging_tests.rs index c067f2053..2fc6fe558 100644 --- a/crates/core/tests/coverage/logging_tests.rs +++ b/crates/core/tests/coverage/logging_tests.rs @@ -201,6 +201,120 @@ fn logging_config_file_requires_logging_section() { assert!(error.contains("requires a [logging] section"), "{error}"); } +#[test] +fn logging_configuration_covers_file_environment_and_sink_validation_edges() { + let temp = tempfile::tempdir().unwrap(); + let config_path = temp.path().join("logging.toml"); + std::fs::write( + &config_path, + r#" +[logging] +level = "error" +stderr_format = "jsonl" +flush_interval_millis = 25 + +[[logging.sinks]] +path = "relay.log" +level = "warn" +format = "human" +queue_capacity = 7 +"#, + ) + .unwrap(); + + { + let _environment = LoggingEnvScope::set(&[ + ("NEMO_RELAY_LOG", None), + ("NEMO_RELAY_LOG_STDERR_FORMAT", None), + ("NEMO_RELAY_LOG_CONFIG_PATH", Some(config_path.as_os_str())), + ]); + let config = LoggingConfig::from_environment().unwrap().unwrap(); + assert_eq!(config.level, LogLevel::Error); + assert_eq!(config.stderr_format, LogFormat::Jsonl); + assert_eq!(config.flush_interval_millis, 25); + assert_eq!( + config.sinks, + vec![LogSinkConfig::File(FileLogSinkConfig { + path: "relay.log".into(), + level: LogLevel::Warn, + format: LogFormat::Human, + queue_capacity: 7, + })] + ); + } + + for (name, document, expected) in [ + ( + "missing path", + "[logging]\n[[logging.sinks]]\nformat = \"jsonl\"\n", + "requires path", + ), + ( + "empty path", + "[logging]\n[[logging.sinks]]\npath = \"\"\n", + "path must not be empty", + ), + ( + "zero queue", + "[logging]\n[[logging.sinks]]\npath = \"relay.log\"\nqueue_capacity = 0\n", + "must be greater than 0", + ), + ( + "oversized queue", + "[logging]\n[[logging.sinks]]\npath = \"relay.log\"\nqueue_capacity = 8193\n", + "exceeds maximum", + ), + ] { + let error = LoggingConfig::from_toml_document(document) + .unwrap_err() + .to_string(); + assert!(error.contains(expected), "{name}: {error}"); + } + + let wrong_extension = temp.path().join("logging.json"); + assert!( + LoggingConfig::from_file_path(&wrong_extension) + .unwrap_err() + .to_string() + .contains(".toml file") + ); + let missing_file = temp.path().join("missing.toml"); + assert!( + LoggingConfig::from_file_path(&missing_file) + .unwrap_err() + .to_string() + .contains("failed to read") + ); + let invalid_file = temp.path().join("invalid.toml"); + std::fs::write(&invalid_file, "[logging\n").unwrap(); + assert!( + LoggingConfig::from_file_path(&invalid_file) + .unwrap_err() + .to_string() + .contains("invalid logging configuration") + ); +} + +#[test] +#[cfg(unix)] +fn logging_environment_rejects_non_unicode_values() { + use std::os::unix::ffi::OsStringExt as _; + + let invalid = OsString::from_vec(vec![0xff]); + let _environment = LoggingEnvScope::set(&[ + ("NEMO_RELAY_LOG", Some(invalid.as_os_str())), + ("NEMO_RELAY_LOG_STDERR_FORMAT", None), + ("NEMO_RELAY_LOG_CONFIG_PATH", None), + ]); + + assert!( + LoggingConfig::from_environment() + .unwrap_err() + .to_string() + .contains("valid Unicode") + ); +} + #[test] fn human_formatter_includes_correlation_and_event_context() { let line = format_event_for_test( @@ -308,13 +422,15 @@ fn file_sink_receives_jsonl_and_preserves_existing_content() { ); runtime.logger.flush(); // AsyncPoolSink flush queues work on the pool; wait briefly for the append to land. - let contents = wait_for_log_line(&path, |contents| contents.lines().count() >= 2); + let contents = wait_for_log_line(&path, |contents| contents.contains("server_started")); runtime.shutdown(); assert!(contents.starts_with("{\"preexisting\":true}\n")); - let mut lines = contents.lines(); - let _preexisting = lines.next().unwrap(); - let record: Value = serde_json::from_str(lines.next().expect("logged line")).unwrap(); + let record: Value = contents + .lines() + .filter_map(|line| serde_json::from_str::(line).ok()) + .find(|record| record["event"] == "server_started") + .expect("server event"); assert_eq!(record["root_relay_id"], root); assert_eq!(record["target"], "nemo_relay.server"); assert_eq!(record["event"], "server_started"); @@ -525,6 +641,43 @@ fn shutdown_drains_async_file_sink_without_waiting() { ); } +#[test] +fn logging_runtime_emits_initialized_and_shutdown_lifecycle_events() { + let _lock = lock_logging_tests(); + let temp = tempfile::tempdir().unwrap(); + let path = temp.path().join("lifecycle.log.jsonl"); + let config = LoggingConfig { + level: LogLevel::Info, + stderr_format: LogFormat::Human, + sinks: vec![LogSinkConfig::File(FileLogSinkConfig { + path: path.clone(), + level: LogLevel::Info, + format: LogFormat::Jsonl, + ..FileLogSinkConfig::default() + })], + ..default_config() + }; + + let runtime = init_logging(&config).unwrap(); + runtime.shutdown(); + + let records = std::fs::read_to_string(&path).expect("lifecycle log file"); + let records = records + .lines() + .map(|line| serde_json::from_str::(line).unwrap()) + .collect::>(); + assert!(records.iter().any(|record| { + record["target"] == "nemo_relay.logging" + && record["event"] == "logging_initialized" + && record["level"] == "info" + })); + assert!(records.iter().any(|record| { + record["target"] == "nemo_relay.logging" + && record["event"] == "logging_shutdown_started" + && record["level"] == "info" + })); +} + #[test] fn default_logging_config_has_stderr_defaults_and_no_sinks() { let config = LoggingConfig::default(); @@ -559,6 +712,34 @@ fn human_and_jsonl_share_root_id_across_destinations_in_formatter() { assert_eq!(record["root_relay_id"], root); } +#[test] +fn trace_level_names_are_consistent_across_formats() { + let human = format_event_for_test( + LogFormat::Human, + "trace-root", + Level::Trace, + "nemo_relay.logging_test", + None, + "", + &[], + ); + let jsonl = format_event_for_test( + LogFormat::Jsonl, + "trace-root", + Level::Trace, + "nemo_relay.logging_test", + None, + "", + &[], + ); + + assert!(human.contains(" TRACE ")); + assert_eq!( + serde_json::from_str::(jsonl.trim_end()).unwrap()["level"], + "trace" + ); +} + #[test] fn stderr_only_logger_builds_without_file_sinks() { let _lock = lock_logging_tests(); @@ -566,6 +747,42 @@ fn stderr_only_logger_builds_without_file_sinks() { runtime.shutdown(); } +#[test] +fn logging_runtime_configures_defaults_from_an_empty_environment() { + let _environment = LoggingEnvScope::set(&[ + ("NEMO_RELAY_LOG", None), + ("NEMO_RELAY_LOG_STDERR_FORMAT", None), + ("NEMO_RELAY_LOG_CONFIG_PATH", None), + ]); + let runtime = LoggingRuntime::configure_from_environment().unwrap(); + runtime.shutdown(); +} + +#[test] +fn unresolved_parent_components_are_normalized_before_sink_creation() { + let _lock = lock_logging_tests(); + let temp = tempfile::tempdir().unwrap(); + let path = temp + .path() + .join("missing") + .join("discarded") + .join("..") + .join("normalized") + .join("relay.log.jsonl"); + let config = LoggingConfig { + sinks: vec![LogSinkConfig::File(FileLogSinkConfig { + path, + ..FileLogSinkConfig::default() + })], + ..default_config() + }; + + let (logger, _pools) = build_logger(&config, "root".into()).unwrap(); + logger.flush(); + + assert!(temp.path().join("missing/normalized").is_dir()); +} + #[test] fn global_level_filter_drops_events_below_process_minimum() { let _lock = lock_logging_tests(); @@ -684,7 +901,11 @@ fn multiple_file_sinks_receive_same_event() { let human = wait_for_log_line(&path_b, |contents| contents.contains("fanout")); runtime.shutdown(); - let record: Value = serde_json::from_str(jsonl.lines().next().unwrap()).unwrap(); + let record: Value = jsonl + .lines() + .map(|line| serde_json::from_str::(line).unwrap()) + .find(|record| record["event"] == "fanout") + .expect("fanout event"); assert_eq!(record["root_relay_id"], root); assert_eq!(record["event"], "fanout"); assert!(human.contains("event=fanout")); diff --git a/crates/core/tests/integration/native_plugin_tests.rs b/crates/core/tests/integration/native_plugin_tests.rs index 5d98c99b4..ca1f3cdec 100644 --- a/crates/core/tests/integration/native_plugin_tests.rs +++ b/crates/core/tests/integration/native_plugin_tests.rs @@ -1768,6 +1768,8 @@ struct BuiltFixture { } fn build_fixture_plugin() -> BuiltFixture { + let _ = spdlog::init_log_crate_proxy(); + log::set_max_level(log::LevelFilter::Info); let source_dir = TempDir::new().expect("fixture source dir"); let fixture_dir = source_dir.path().join("native_plugin"); let fixture_src_dir = fixture_dir.join("src"); diff --git a/crates/core/tests/integration/subscriber_dispatcher_tests.rs b/crates/core/tests/integration/subscriber_dispatcher_tests.rs index 4a335c61f..e83fc7d6d 100644 --- a/crates/core/tests/integration/subscriber_dispatcher_tests.rs +++ b/crates/core/tests/integration/subscriber_dispatcher_tests.rs @@ -15,6 +15,8 @@ use nemo_relay::api::subscriber::{deregister_subscriber, flush_subscribers, regi static TEST_MUTEX: Mutex<()> = Mutex::new(()); fn reset_global() { + let _ = spdlog::init_log_crate_proxy(); + log::set_max_level(log::LevelFilter::Info); let ctx = global_context(); let mut state = ctx.write().unwrap(); *state = NemoRelayContextState::new(); diff --git a/crates/core/tests/integration/worker_plugin_tests.rs b/crates/core/tests/integration/worker_plugin_tests.rs index 350f8ac72..8ac588a53 100644 --- a/crates/core/tests/integration/worker_plugin_tests.rs +++ b/crates/core/tests/integration/worker_plugin_tests.rs @@ -37,6 +37,11 @@ use uuid::Uuid; static WORKER_PLUGIN_TEST_LOCK: tokio::sync::Mutex<()> = tokio::sync::Mutex::const_new(()); +fn enable_operational_logs() { + let _ = spdlog::init_log_crate_proxy(); + log::set_max_level(log::LevelFilter::Info); +} + #[test] fn worker_activation_with_no_specs_is_empty() { let activation = load_worker_plugins(Vec::::new()) @@ -1235,6 +1240,7 @@ impl BuiltWorkerFixture { } fn build_fixture_worker() -> BuiltWorkerFixture { + enable_operational_logs(); static FIXTURE_BINARY: OnceLock = OnceLock::new(); let binary_path = FIXTURE_BINARY.get_or_init(|| { let fixture_dir = fixture_root(); diff --git a/crates/core/tests/unit/codec/response_tests.rs b/crates/core/tests/unit/codec/response_tests.rs index 93d2935b1..b028264c3 100644 --- a/crates/core/tests/unit/codec/response_tests.rs +++ b/crates/core/tests/unit/codec/response_tests.rs @@ -773,6 +773,8 @@ fn test_pricing_resolver_validates_custom_source_catalogs() { #[test] fn test_pricing_plugin_configures_process_resolver_and_clears_to_default() { + let _ = spdlog::init_log_crate_proxy(); + log::set_max_level(log::LevelFilter::Info); let _runtime_guard = crate::shared_runtime::runtime_owner_test_mutex() .lock() .unwrap(); diff --git a/crates/core/tests/unit/dynamic_worker_tests.rs b/crates/core/tests/unit/dynamic_worker_tests.rs index 1e7c31892..a6669254a 100644 --- a/crates/core/tests/unit/dynamic_worker_tests.rs +++ b/crates/core/tests/unit/dynamic_worker_tests.rs @@ -4,6 +4,7 @@ use std::sync::{Arc, Mutex}; use crate::api::event::{BaseEvent, MarkEvent}; +use crate::api::runtime::NemoRelayContextState; use nemo_relay_worker_proto::json_envelope; use nemo_relay_worker_proto::v1::invoke_response::Result as InvokeResult; use nemo_relay_worker_proto::v1::plugin_worker_server::{PluginWorker, PluginWorkerServer}; @@ -27,8 +28,14 @@ use super::*; const ACTIVATION_ID: &str = "activation-test"; const AUTH_TOKEN: &str = "auth-test"; +fn enable_operational_logs() { + let _ = spdlog::init_log_crate_proxy(); + log::set_max_level(log::LevelFilter::Info); +} + #[test] fn python_environment_resolution_requires_lifecycle_managed_path() { + enable_operational_logs(); let plugin_id = "acme.python"; let digest = Sha256::digest(plugin_id.as_bytes()) .iter() @@ -65,6 +72,7 @@ fn python_environment_resolution_requires_lifecycle_managed_path() { #[test] fn python_worker_launch_clears_host_python_environment() { + enable_operational_logs(); let mut command = Command::new("python"); clear_host_python_environment(&mut command); let removed = command @@ -78,6 +86,7 @@ fn python_worker_launch_clears_host_python_environment() { #[test] fn response_helpers_cover_error_and_unexpected_shapes() { + enable_operational_logs(); let worker_error = WorkerError { code: "worker.failed".into(), message: "boom".into(), @@ -181,6 +190,7 @@ fn response_helpers_cover_error_and_unexpected_shapes() { #[test] fn envelope_and_error_helpers_cover_failure_paths() { + enable_operational_logs(); assert!( required_envelope(None, "required test") .expect_err("missing envelope should fail") @@ -222,6 +232,7 @@ fn envelope_and_error_helpers_cover_failure_paths() { #[test] fn registration_plan_and_scope_type_helpers_validate_edges() { + enable_operational_logs(); let empty_name = validate_registration_plan( "fixture_worker", &RegisterResponse { @@ -317,6 +328,7 @@ fn registration_plan_and_scope_type_helpers_validate_edges() { #[test] fn relay_compatibility_and_blocking_helpers_cover_local_edges() { + enable_operational_logs(); assert!( validate_relay_compatibility(None) .expect_err("missing relay compatibility should fail") @@ -340,6 +352,7 @@ fn relay_compatibility_and_blocking_helpers_cover_local_edges() { #[test] #[cfg(unix)] fn worker_endpoints_fail_when_host_socket_cannot_bind() { + enable_operational_logs(); let activation_dir = std::env::temp_dir().join(format!("nmrw-unit-{}", Uuid::now_v7())); let host_socket = activation_dir.join("host.sock"); std::fs::create_dir_all(&host_socket).expect("host socket directory should be created"); @@ -359,6 +372,7 @@ fn worker_endpoints_fail_when_host_socket_cannot_bind() { #[tokio::test(flavor = "multi_thread")] async fn callback_helpers_cover_worker_response_edges() { + enable_operational_logs(); let worker_error = WorkerError { code: "worker.failed".into(), message: "boom".into(), @@ -525,6 +539,7 @@ async fn callback_helpers_cover_worker_response_edges() { #[tokio::test(flavor = "multi_thread")] async fn callback_stream_transport_error_surfaces_to_host_stream() { + enable_operational_logs(); let (callback, _shutdown) = fake_callback_service(|_| InvokeResponse { result: Some(InvokeResult::Empty(EmptyResult {})), }) @@ -552,6 +567,7 @@ async fn callback_stream_transport_error_surfaces_to_host_stream() { #[tokio::test(flavor = "multi_thread")] async fn callback_stream_stops_when_host_receiver_is_dropped() { + enable_operational_logs(); let (yield_tx, yield_rx) = oneshot::channel(); let (stream_dropped_tx, stream_dropped_rx) = oneshot::channel(); let stream_dropped_tx = Arc::new(Mutex::new(Some(stream_dropped_tx))); @@ -612,6 +628,7 @@ async fn callback_stream_stops_when_host_receiver_is_dropped() { #[tokio::test(flavor = "multi_thread")] async fn callback_timeout_sends_explicit_worker_cancellation() { + enable_operational_logs(); let (started_tx, started_rx) = oneshot::channel(); let started_tx = Arc::new(Mutex::new(Some(started_tx))); let (callback, _shutdown, mut cancel_rx) = fake_callback_service_with_handlers( @@ -669,6 +686,7 @@ async fn callback_timeout_sends_explicit_worker_cancellation() { #[tokio::test(flavor = "multi_thread")] async fn dropping_callback_future_cancels_worker_and_cleans_host_state() { + enable_operational_logs(); let (started_tx, started_rx) = oneshot::channel(); let started_tx = Arc::new(Mutex::new(Some(started_tx))); let (callback, _shutdown, mut cancel_rx) = fake_callback_service_with_handlers( @@ -844,6 +862,7 @@ async fn dropping_callback_future_cancels_worker_and_cleans_host_state() { #[test] fn invocation_cleanup_releases_host_state_locks_before_unwinding() { + enable_operational_logs(); let state = Arc::new(WorkerHostRuntimeState::new( ACTIVATION_ID.into(), AUTH_TOKEN.into(), @@ -910,6 +929,7 @@ fn invocation_cleanup_releases_host_state_locks_before_unwinding() { #[tokio::test(flavor = "multi_thread")] async fn dropping_host_stream_sends_explicit_worker_cancellation() { + enable_operational_logs(); let (yield_tx, yield_rx) = oneshot::channel(); let yield_rx = Arc::new(Mutex::new(Some(yield_rx))); let (callback, _shutdown, mut cancel_rx) = fake_callback_service_with_handlers( @@ -967,6 +987,7 @@ async fn dropping_host_stream_sends_explicit_worker_cancellation() { #[tokio::test(flavor = "multi_thread")] async fn install_registrations_covers_registry_error_edges() { + enable_operational_logs(); for surface in [ RegistrationSurface::Subscriber, RegistrationSurface::ToolSanitizeRequestGuardrail, @@ -1025,8 +1046,152 @@ async fn install_registrations_covers_registry_error_edges() { ); } +#[tokio::test(flavor = "multi_thread")] +async fn installed_fail_open_callbacks_preserve_original_values() { + struct RuntimeCleanup { + registrations: Option, + } + + impl Drop for RuntimeCleanup { + fn drop(&mut self) { + if let Some(context) = self.registrations.take() { + let mut registrations = context.into_registrations(); + crate::plugin::rollback_registrations(&mut registrations); + } + let context = crate::api::runtime::global_context(); + *context.write().unwrap_or_else(|error| error.into_inner()) = + NemoRelayContextState::new(); + crate::shared_runtime::reset_runtime_owner_for_tests(); + } + } + + enable_operational_logs(); + let registrations = vec![ + registration(RegistrationSurface::Subscriber, "fallback_subscriber"), + registration(RegistrationSurface::MarkSanitizeGuardrail, "fallback_mark"), + registration( + RegistrationSurface::ScopeSanitizeStartGuardrail, + "fallback_scope_start", + ), + registration( + RegistrationSurface::ScopeSanitizeEndGuardrail, + "fallback_scope_end", + ), + registration( + RegistrationSurface::ToolSanitizeRequestGuardrail, + "fallback_tool_request", + ), + registration( + RegistrationSurface::ToolSanitizeResponseGuardrail, + "fallback_tool_response", + ), + registration( + RegistrationSurface::LlmSanitizeRequestGuardrail, + "fallback_llm_request", + ), + registration( + RegistrationSurface::LlmSanitizeResponseGuardrail, + "fallback_llm_response", + ), + ]; + let (mut instance, _instance_shutdown) = fake_worker_instance(registrations).await; + let (error_client, _error_shutdown) = fake_worker_client(|_| InvokeResponse { + result: Some(InvokeResult::Error(WorkerError { + code: "worker.failed".into(), + message: "callback unavailable".into(), + retryable: false, + })), + }) + .await; + instance.client = error_client; + + let _runtime_guard = crate::shared_runtime::runtime_owner_test_mutex() + .lock() + .unwrap_or_else(|error| error.into_inner()); + crate::shared_runtime::reset_runtime_owner_for_tests(); + let context = crate::api::runtime::global_context(); + *context.write().unwrap() = NemoRelayContextState::new(); + + let mut registration_context = PluginRegistrationContext::new(); + instance + .install_registrations(&mut registration_context) + .expect("worker registrations should install"); + let _cleanup = RuntimeCleanup { + registrations: Some(registration_context), + }; + + let event = Event::Mark(MarkEvent::new( + BaseEvent::builder() + .name("fail-open-event") + .data(json!({"preserved": true})) + .build(), + None, + None, + )); + let tool_request = json!({"request": "preserved"}); + let tool_response = json!({"response": "preserved"}); + let llm_request = valid_llm_request(); + let llm_response = json!({"response": "preserved"}); + + { + let state = context.read().unwrap(); + let subscribers = state.collect_event_subscribers(&[]); + NemoRelayContextState::emit_event(&event, &subscribers); + + for registry in [ + &state.mark_sanitize_guardrails, + &state.scope_sanitize_start_guardrails, + &state.scope_sanitize_end_guardrails, + ] { + let entries = NemoRelayContextState::event_sanitize_entries(registry, &[]); + assert_eq!( + NemoRelayContextState::event_sanitize_snapshot_chain(event.clone(), &entries) + .data(), + event.data() + ); + } + + let entries = state.tool_sanitize_request_entries(&[]); + assert_eq!( + NemoRelayContextState::tool_sanitize_request_snapshot_chain( + "tool", + tool_request.clone(), + &entries, + ), + tool_request + ); + let entries = state.tool_sanitize_response_entries(&[]); + assert_eq!( + NemoRelayContextState::tool_sanitize_response_snapshot_chain( + "tool", + tool_response.clone(), + &entries, + ), + tool_response + ); + let entries = state.llm_sanitize_request_entries(&[]); + assert_eq!( + NemoRelayContextState::llm_sanitize_request_snapshot_chain( + llm_request.clone(), + &entries, + ), + llm_request + ); + let entries = state.llm_sanitize_response_entries(&[]); + assert_eq!( + NemoRelayContextState::llm_sanitize_response_snapshot_chain( + llm_response.clone(), + &entries, + ), + llm_response + ); + } + crate::api::subscriber::flush_subscribers().expect("subscriber callback should flush"); +} + #[tokio::test(flavor = "multi_thread")] async fn adapter_register_rejects_config_drift_even_without_validation_call() { + enable_operational_logs(); let (instance, _shutdown) = fake_worker_instance(Vec::new()).await; let adapter = WorkerPluginAdapter { plugin_kind: "fixture_worker".into(), @@ -1045,6 +1210,7 @@ async fn adapter_register_rejects_config_drift_even_without_validation_call() { #[tokio::test] async fn host_runtime_service_covers_auth_scope_and_ack_errors() { + enable_operational_logs(); let state = Arc::new(WorkerHostRuntimeState::new( ACTIVATION_ID.into(), AUTH_TOKEN.into(), @@ -1188,6 +1354,7 @@ async fn host_runtime_service_covers_auth_scope_and_ack_errors() { #[tokio::test] async fn host_runtime_service_reports_poisoned_internal_locks() { + enable_operational_logs(); let state = Arc::new(WorkerHostRuntimeState::new( ACTIVATION_ID.into(), AUTH_TOKEN.into(), @@ -1263,11 +1430,13 @@ async fn host_runtime_service_reports_poisoned_internal_locks() { #[test] fn owned_worker_runtime_drop_is_idempotent_when_runtime_already_taken() { + enable_operational_logs(); drop(OwnedWorkerRuntime { runtime: None }); } #[tokio::test] async fn host_runtime_service_covers_continuation_errors_and_stream_items() { + enable_operational_logs(); let state = Arc::new(WorkerHostRuntimeState::new( ACTIVATION_ID.into(), AUTH_TOKEN.into(), @@ -1440,6 +1609,7 @@ fn callback_for_client( ( WorkerPluginCallback { activation_id: ACTIVATION_ID.into(), + plugin_kind: "fixture_worker".into(), runtime: tokio::runtime::Handle::current(), client, host_state: state, @@ -1451,6 +1621,7 @@ fn callback_for_client( async fn fake_worker_instance( registrations: Vec, ) -> (WorkerPluginInstance, oneshot::Sender<()>) { + enable_operational_logs(); let (client, shutdown_tx) = fake_worker_client(|_| InvokeResponse { result: Some(InvokeResult::Empty(EmptyResult {})), }) diff --git a/crates/core/tests/unit/llm_api_tests.rs b/crates/core/tests/unit/llm_api_tests.rs index 625d5bf7c..ca541caa3 100644 --- a/crates/core/tests/unit/llm_api_tests.rs +++ b/crates/core/tests/unit/llm_api_tests.rs @@ -33,6 +33,8 @@ use crate::json::Json; use crate::{codec::optimization::LlmOptimizationContribution, codec::response::PricingResolver}; fn reset_global() { + let _ = spdlog::init_log_crate_proxy(); + log::set_max_level(log::LevelFilter::Info); crate::shared_runtime::reset_runtime_owner_for_tests(); let context = global_context(); *context.write().unwrap() = NemoRelayContextState::new(); @@ -650,6 +652,36 @@ fn rejected_optimization_mark_queue_keeps_cursor_and_summary_evidence() { assert_eq!(summary.contributions[0].producer, "test"); } +#[test] +fn unavailable_runtime_owner_skips_optimization_mark_delivery() { + let _guard = lock_global_runtime(); + reset_global(); + crate::shared_runtime::initialize_shared_runtime_binding("python").unwrap(); + let owner = format!( + "pid={};binding=rust;version={}", + std::process::id(), + env!("CARGO_PKG_VERSION").split('.').next().unwrap() + ); + // SAFETY: The runtime-owner test mutex serializes this process-global test variable. + unsafe { std::env::set_var("NEMO_RELAY_RUNTIME_OWNER", owner) }; + + let handle = LlmHandle::builder().name("owner-unavailable").build(); + assert!( + handle + .optimization_recorder + .record(LlmOptimizationContribution::new( + "test", + "owner_unavailable" + )) + ); + emit_optimization_marks_with(&handle, &[], Some, |_event, _subscribers| { + panic!("an unavailable runtime owner must skip mark delivery") + }); + assert_eq!(handle.optimization_recorder.unemitted().len(), 1); + + reset_global(); +} + #[test] fn unavailable_mark_sanitizer_does_not_acknowledge_the_delivery_cursor() { let _guard = lock_global_runtime(); diff --git a/crates/core/tests/unit/observability/atof_tests.rs b/crates/core/tests/unit/observability/atof_tests.rs index 4d5dc84f9..7bf2b8c14 100644 --- a/crates/core/tests/unit/observability/atof_tests.rs +++ b/crates/core/tests/unit/observability/atof_tests.rs @@ -26,6 +26,11 @@ use std::sync::Mutex; use std::time::{SystemTime, UNIX_EPOCH}; use uuid::Uuid; +fn enable_operational_logs() { + let _ = spdlog::init_log_crate_proxy(); + log::set_max_level(log::LevelFilter::Info); +} + fn temp_dir(prefix: &str) -> PathBuf { let id = SystemTime::now() .duration_since(UNIX_EPOCH) @@ -445,22 +450,11 @@ fn endpoint_http_helper_edges_are_safe() { None, "unknown field name policies should be rejected" ); - assert_eq!(truncate_log_body(" short body "), "short body"); - - let long_body = "é".repeat(1_025); - let truncated = truncate_log_body(&long_body); - assert!(truncated.ends_with("... ")); - assert_eq!( - truncated - .trim_end_matches("... ") - .chars() - .count(), - 1_024 - ); } #[test] fn append_mode_preserves_existing_lines() { + enable_operational_logs(); let dir = temp_dir("atof-append"); let path = dir.join("events.jsonl"); fs::write(&path, "{\"existing\":true}\n").unwrap(); @@ -574,6 +568,7 @@ fn subscriber_writes_canonical_event_jsonl() { #[test] #[cfg(feature = "atof-streaming")] fn streaming_sink_receives_raw_atof_events() { + enable_operational_logs(); let dir = temp_dir("atof-streaming-http"); let (url, captures) = start_http_capture_server(3); let exporter = AtofExporter::new( @@ -614,6 +609,7 @@ fn streaming_sink_receives_raw_atof_events() { #[test] #[cfg(feature = "atof-streaming")] fn websocket_endpoint_receives_fifo_json_text_events() { + enable_operational_logs(); let dir = temp_dir("atof-streaming-websocket"); let listener = TcpListener::bind("127.0.0.1:0").unwrap(); listener.set_nonblocking(true).unwrap(); @@ -646,6 +642,7 @@ fn websocket_endpoint_receives_fifo_json_text_events() { #[test] #[cfg(feature = "atof-streaming")] fn websocket_flush_drains_events_queued_before_reconnect() { + enable_operational_logs(); let dir = temp_dir("atof-streaming-websocket-reconnect"); let listener = TcpListener::bind("127.0.0.1:0").unwrap(); let local_addr = listener.local_addr().unwrap(); @@ -1470,6 +1467,7 @@ fn endpoint_validation_rejects_empty_timeout_and_invalid_headers() { #[test] #[cfg(feature = "atof-streaming")] fn endpoint_worker_helpers_acknowledge_flush_and_close_error_paths() { + enable_operational_logs(); let (body_tx, body) = ndjson_body_channel(); drop(body); send_ndjson_event(0, &body_tx, "{}".into()); @@ -1498,9 +1496,26 @@ fn endpoint_worker_helpers_acknowledge_flush_and_close_error_paths() { .unwrap(); } +#[test] +#[cfg(feature = "atof-streaming")] +fn endpoint_worker_reports_flush_and_close_timeouts() { + enable_operational_logs(); + let (sender, _receiver) = tokio::sync::mpsc::unbounded_channel(); + let worker = AtofEndpointWorker { + sender, + timeout: std::time::Duration::from_millis(1), + index: 7, + transport: AtofEndpointTransport::HttpPost, + }; + + worker.flush(); + worker.close(); +} + #[test] #[cfg(feature = "atof-streaming")] fn http_endpoint_worker_acknowledges_flush_close_and_logs_http_errors() { + enable_operational_logs(); let listener = TcpListener::bind("127.0.0.1:0").unwrap(); let url = format!("http://{}", listener.local_addr().unwrap()); let server = std::thread::spawn(move || { @@ -1548,6 +1563,7 @@ fn http_endpoint_worker_acknowledges_flush_close_and_logs_http_errors() { #[test] #[cfg(feature = "atof-streaming")] fn http_endpoint_worker_disables_invalid_headers_and_drains_control_messages() { + enable_operational_logs(); let mut headers = std::collections::HashMap::new(); headers.insert("bad header".to_string(), "ok".to_string()); let (tx, rx) = tokio::sync::mpsc::unbounded_channel(); @@ -1584,9 +1600,78 @@ fn http_endpoint_worker_disables_invalid_headers_and_drains_control_messages() { worker.join().unwrap(); } +#[test] +#[cfg(feature = "atof-streaming")] +fn http_endpoint_worker_reports_request_transport_failure() { + enable_operational_logs(); + let (tx, rx) = tokio::sync::mpsc::unbounded_channel(); + let worker = std::thread::spawn(move || { + tokio::runtime::Runtime::new().unwrap().block_on(async { + run_http_post_endpoint( + 0, + AtofEndpointConfig::new( + "http://127.0.0.1:0/events", + AtofEndpointTransport::HttpPost, + ) + .with_timeout_millis(100), + rx, + ) + .await; + }); + }); + + tx.send(EndpointMessage::Event("{\"kind\":\"mark\"}".into())) + .unwrap(); + let (close_tx, close_rx) = std::sync::mpsc::channel(); + tx.send(EndpointMessage::Close(close_tx)).unwrap(); + close_rx + .recv_timeout(std::time::Duration::from_secs(1)) + .unwrap(); + worker.join().unwrap(); +} + +#[test] +#[cfg(feature = "atof-streaming")] +fn ndjson_endpoint_worker_disables_invalid_headers_and_drains_control_messages() { + enable_operational_logs(); + let mut headers = std::collections::HashMap::new(); + headers.insert("bad header".to_string(), "ok".to_string()); + let (tx, rx) = tokio::sync::mpsc::unbounded_channel(); + let worker = std::thread::spawn(move || { + tokio::runtime::Runtime::new().unwrap().block_on(async { + run_ndjson_endpoint( + 0, + AtofEndpointConfig { + url: "http://127.0.0.1:9/events".into(), + transport: AtofEndpointTransport::Ndjson, + headers, + header_env: std::collections::HashMap::new(), + timeout_millis: 1, + field_name_policy: AtofEndpointFieldNamePolicy::Preserve, + }, + rx, + ) + .await; + }); + }); + + let (flush_tx, flush_rx) = std::sync::mpsc::channel(); + tx.send(EndpointMessage::Flush(flush_tx)).unwrap(); + let (close_tx, close_rx) = std::sync::mpsc::channel(); + tx.send(EndpointMessage::Close(close_tx)).unwrap(); + flush_rx + .recv_timeout(std::time::Duration::from_secs(1)) + .unwrap(); + close_rx + .recv_timeout(std::time::Duration::from_secs(1)) + .unwrap(); + worker.join().unwrap(); +} + #[test] #[cfg(feature = "atof-streaming")] fn websocket_helpers_cover_invalid_headers_and_timeout_reconnect_path() { + enable_operational_logs(); let mut headers = std::collections::HashMap::new(); headers.insert("bad header".to_string(), "ok".to_string()); let config = AtofEndpointConfig { @@ -1602,14 +1687,17 @@ fn websocket_helpers_cover_invalid_headers_and_timeout_reconnect_path() { let mut socket = None; let mut pending = std::collections::VecDeque::from(["{\"kind\":\"mark\"}".to_string()]); - assert!(!drain_websocket_pending(0, &config, &mut socket, &mut pending).await); + let mut retry = WebSocketRetryState::default(); + assert!(!drain_websocket_pending(0, &config, &mut socket, &mut pending, &mut retry).await); assert_eq!(pending.len(), 1); + assert_eq!(retry.attempts, 1); }); } #[test] #[cfg(feature = "atof-streaming")] fn ndjson_upload_close_timeout_acknowledges_close() { + enable_operational_logs(); let request = tokio::runtime::Runtime::new().unwrap().block_on(async { let request: tokio::task::JoinHandle> = tokio::spawn(async { @@ -1626,8 +1714,57 @@ fn ndjson_upload_close_timeout_acknowledges_close() { assert!(request); } +#[test] +#[cfg(feature = "atof-streaming")] +fn ndjson_upload_completion_reports_success_http_upload_and_task_failures() { + enable_operational_logs(); + let runtime = tokio::runtime::Runtime::new().unwrap(); + + for response in [ + "HTTP/1.1 200 OK\r\nContent-Length: 0\r\nConnection: close\r\n\r\n", + "HTTP/1.1 503 Service Unavailable\r\nContent-Length: 0\r\nConnection: close\r\n\r\n", + ] { + let listener = TcpListener::bind("127.0.0.1:0").unwrap(); + let url = format!("http://{}", listener.local_addr().unwrap()); + let server = std::thread::spawn(move || { + let (mut stream, _) = listener.accept().unwrap(); + let _ = read_http_request(&mut stream); + stream.write_all(response.as_bytes()).unwrap(); + }); + runtime.block_on(async { + let request = tokio::spawn(async move { reqwest::get(url).await }); + let (done_tx, done_rx) = std::sync::mpsc::channel(); + finish_ndjson_upload(2, request, std::time::Duration::from_secs(5), done_tx).await; + done_rx + .recv_timeout(std::time::Duration::from_secs(1)) + .unwrap(); + }); + server.join().unwrap(); + } + + runtime.block_on(async { + let upload_error = tokio::spawn(async { reqwest::get("http://127.0.0.1:0").await }); + let (done_tx, done_rx) = std::sync::mpsc::channel(); + finish_ndjson_upload(3, upload_error, std::time::Duration::from_secs(5), done_tx).await; + done_rx + .recv_timeout(std::time::Duration::from_secs(1)) + .unwrap(); + + let task_error = tokio::spawn(async { + std::future::pending::>().await + }); + task_error.abort(); + let (done_tx, done_rx) = std::sync::mpsc::channel(); + finish_ndjson_upload(4, task_error, std::time::Duration::from_secs(5), done_tx).await; + done_rx + .recv_timeout(std::time::Duration::from_secs(1)) + .unwrap(); + }); +} + #[test] fn force_flush_reports_stored_subscriber_failure() { + enable_operational_logs(); let dir = temp_dir("atof-stored-failure"); let exporter = AtofExporter::new( AtofExporterConfig::new() diff --git a/crates/core/tests/unit/observability/openinference_tests.rs b/crates/core/tests/unit/observability/openinference_tests.rs index 25fca6174..a7b52ea17 100644 --- a/crates/core/tests/unit/observability/openinference_tests.rs +++ b/crates/core/tests/unit/observability/openinference_tests.rs @@ -43,6 +43,8 @@ impl Drop for ResetPricingResolverGuard { } fn reset_global() { + let _ = spdlog::init_log_crate_proxy(); + log::set_max_level(log::LevelFilter::Info); crate::shared_runtime::reset_runtime_owner_for_tests(); let context = global_context(); *context.write().unwrap() = NemoRelayContextState::new(); @@ -3193,12 +3195,15 @@ fn scope_end_output_payload_is_exported_to_openinference_attributes() { #[test] fn scope_end_metadata_sets_openinference_span_status() { + let _ = spdlog::init_log_crate_proxy(); + log::set_max_level(log::LevelFilter::Info); let cases = [ ( json!({"otel.status_code": "ERROR", "otel.status_description": "failed"}), Status::error("failed".to_string()), ), (json!({"otel.status_code": "OK"}), Status::Ok), + (json!({"otel.status_code": "INVALID"}), Status::Unset), (json!({}), Status::Unset), ]; diff --git a/crates/core/tests/unit/observability/otel_tests.rs b/crates/core/tests/unit/observability/otel_tests.rs index bbdcd082c..cec581fca 100644 --- a/crates/core/tests/unit/observability/otel_tests.rs +++ b/crates/core/tests/unit/observability/otel_tests.rs @@ -284,6 +284,8 @@ fn openai_chat_provider_response(model_id: &str) -> Json { } fn reset_global() { + let _ = spdlog::init_log_crate_proxy(); + log::set_max_level(log::LevelFilter::Info); crate::shared_runtime::reset_runtime_owner_for_tests(); let context = global_context(); *context.write().unwrap() = NemoRelayContextState::new(); diff --git a/crates/core/tests/unit/observability/plugin_component_tests.rs b/crates/core/tests/unit/observability/plugin_component_tests.rs index 8311f37ce..6c42e717d 100644 --- a/crates/core/tests/unit/observability/plugin_component_tests.rs +++ b/crates/core/tests/unit/observability/plugin_component_tests.rs @@ -77,6 +77,62 @@ fn start_http_capture_server(expected_requests: usize) -> (String, Arc (String, std::thread::JoinHandle<()>) { + let listener = TcpListener::bind("127.0.0.1:0").unwrap(); + let url = format!("http://{}", listener.local_addr().unwrap()); + let server = std::thread::spawn(move || { + listener.set_nonblocking(true).unwrap(); + let deadline = std::time::Instant::now() + std::time::Duration::from_secs(2); + let (mut stream, _) = loop { + match listener.accept() { + Ok(connection) => break connection, + Err(error) if error.kind() == std::io::ErrorKind::WouldBlock => { + if std::time::Instant::now() >= deadline { + return; + } + std::thread::sleep(std::time::Duration::from_millis(10)); + } + Err(_) => return, + } + }; + stream + .set_read_timeout(Some(std::time::Duration::from_secs(2))) + .unwrap(); + let mut request = Vec::new(); + let mut byte = [0_u8; 1]; + while !request.ends_with(b"\r\n\r\n") { + if stream.read_exact(&mut byte).is_err() { + return; + } + request.push(byte[0]); + } + let headers = String::from_utf8_lossy(&request); + let length = headers + .lines() + .find_map(|line| { + line.split_once(':').and_then(|(name, value)| { + name.eq_ignore_ascii_case("content-length") + .then_some(value.trim()) + }) + }) + .and_then(|value| value.parse::().ok()); + let Some(length) = length else { + return; + }; + let mut body = vec![0_u8; length]; + if stream.read_exact(&mut body).is_err() { + return; + } + write!( + stream, + "HTTP/1.1 {status}\r\nContent-Length: 0\r\nConnection: close\r\n\r\n" + ) + .unwrap(); + }); + (url, server) +} + #[cfg(feature = "atof-streaming")] fn wait_for_captures(captures: &Arc>>, expected: usize) -> Vec { for _ in 0..100 { @@ -90,6 +146,8 @@ fn wait_for_captures(captures: &Arc>>, expected: usize) -> Vec } fn reset_runtime() { + let _ = spdlog::init_log_crate_proxy(); + log::set_max_level(log::LevelFilter::Info); let _ = clear_plugin_configuration(); crate::shared_runtime::reset_runtime_owner_for_tests(); let context = global_context(); @@ -1064,6 +1122,50 @@ fn atof_stream_sinks_fan_out_and_teardown_all_workers() { } } +#[test] +#[cfg(all(feature = "atof-streaming", feature = "object-store"))] +fn atif_remote_storage_validates_s3_configuration_and_http_access_outcomes() { + let _guard = crate::observability::test_mutex().lock().unwrap(); + reset_runtime(); + + let secret_var = format!("NEMO_RELAY_TEST_S3_SECRET_{}", std::process::id()); + // SAFETY: The variable name is unique to this test process and is removed before returning. + unsafe { std::env::set_var(&secret_var, "test-secret") }; + let s3 = AtifStorageConfig::S3(S3StorageConfig { + bucket: "test-bucket".into(), + key_prefix: Some("trajectories".into()), + access_key_id: Some("test-access-key".into()), + secret_access_key_var: Some(secret_var.clone()), + session_token_var: None, + region: Some("us-east-1".into()), + endpoint_url: Some("http://127.0.0.1:9".into()), + allow_http: Some(true), + }); + let storage = build_atif_storage(3, &s3).expect("S3 client configuration should resolve"); + drop(storage); + // SAFETY: Cleanup of the test-only environment variable. + unsafe { std::env::remove_var(&secret_var) }; + + for (status, succeeds) in [("200 OK", true), ("503 Service Unavailable", false)] { + let (endpoint, server) = start_http_status_server(status); + let storage = AtifRemoteStorage::from_config( + 4, + &AtifStorageConfig::Http(HttpStorageConfig { + endpoint, + headers: std::collections::HashMap::new(), + header_env: std::collections::HashMap::new(), + timeout_millis: 5_000, + }), + ) + .unwrap(); + + let result = storage.put("trajectory.json", "session", b"{}"); + assert_eq!(result.is_ok(), succeeds); + drop(storage); + server.join().unwrap(); + } +} + #[test] fn atif_defaults_create_one_file_per_top_level_agent() { let _guard = crate::observability::test_mutex().lock().unwrap(); diff --git a/crates/core/tests/unit/plugin_tests.rs b/crates/core/tests/unit/plugin_tests.rs index fe70f1385..b24c0591b 100644 --- a/crates/core/tests/unit/plugin_tests.rs +++ b/crates/core/tests/unit/plugin_tests.rs @@ -422,6 +422,8 @@ impl Plugin for FailingDeregisterPlugin { } fn reset_global() { + let _ = spdlog::init_log_crate_proxy(); + log::set_max_level(log::LevelFilter::Info); crate::shared_runtime::reset_runtime_owner_for_tests(); let ctx = global_context(); let mut state = ctx.write().unwrap(); diff --git a/crates/core/tests/unit/plugins/nemo_guardrails/component_tests.rs b/crates/core/tests/unit/plugins/nemo_guardrails/component_tests.rs index adc468fa7..b1318e7f7 100644 --- a/crates/core/tests/unit/plugins/nemo_guardrails/component_tests.rs +++ b/crates/core/tests/unit/plugins/nemo_guardrails/component_tests.rs @@ -41,6 +41,8 @@ use serde_json::json; const TEST_TIMEOUT: Duration = Duration::from_secs(5); fn reset_runtime() { + let _ = spdlog::init_log_crate_proxy(); + log::set_max_level(log::LevelFilter::Info); let _ = clear_plugin_configuration(); crate::shared_runtime::reset_runtime_owner_for_tests(); let context = global_context(); diff --git a/crates/core/tests/unit/plugins/nemo_guardrails/local_python_tests.rs b/crates/core/tests/unit/plugins/nemo_guardrails/local_python_tests.rs index 214fa567e..ec38fdb4c 100644 --- a/crates/core/tests/unit/plugins/nemo_guardrails/local_python_tests.rs +++ b/crates/core/tests/unit/plugins/nemo_guardrails/local_python_tests.rs @@ -138,6 +138,8 @@ struct FakeGuardrails { #[cfg(unix)] impl FakeGuardrails { fn new(version: &str) -> Self { + let _ = spdlog::init_log_crate_proxy(); + log::set_max_level(log::LevelFilter::Info); let id = NEXT_FIXTURE_ID.fetch_add(1, Ordering::Relaxed); let module_name = format!("fake_guardrails_{id}"); let root = std::env::temp_dir().join(format!( @@ -204,6 +206,65 @@ fn python3_available() -> bool { .unwrap_or(false) } +#[test] +#[cfg(unix)] +fn shutdown_handles_an_already_reaped_worker_process() { + let _ = spdlog::init_log_crate_proxy(); + log::set_max_level(log::LevelFilter::Info); + let mut child = Command::new("true").spawn().unwrap(); + child.wait().unwrap(); + let worker = LocalGuardrailsWorker { + writer: Mutex::new(None), + child: Mutex::new(child), + waiters: Arc::new(Mutex::new(HashMap::new())), + stream_events: Arc::new(Mutex::new(HashMap::new())), + next_id: AtomicU64::new(0), + shutdown_started: AtomicBool::new(false), + }; + + worker.shutdown(); +} + +#[tokio::test] +#[cfg(unix)] +async fn request_timeout_stops_an_unresponsive_worker() { + let _ = spdlog::init_log_crate_proxy(); + log::set_max_level(log::LevelFilter::Info); + let child = Command::new("sleep").arg("60").spawn().unwrap(); + let (sender, receiver) = std_mpsc::channel::(); + let waiters = Arc::new(Mutex::new(HashMap::new())); + let stream_events = Arc::new(Mutex::new(HashMap::new())); + let closed_waiters = Arc::clone(&waiters); + let closed_stream_events = Arc::clone(&stream_events); + let handle = thread::spawn(move || { + while receiver.recv().is_ok() { + thread::sleep(Duration::from_millis(50)); + notify_worker_closed( + &closed_waiters, + &closed_stream_events, + "test worker closed".into(), + ); + } + }); + let worker = LocalGuardrailsWorker { + writer: Mutex::new(Some(WorkerCommandWriter { + sender, + error: Arc::new(Mutex::new(None)), + handle: Some(handle), + })), + child: Mutex::new(child), + waiters, + stream_events, + next_id: AtomicU64::new(0), + shutdown_started: AtomicBool::new(false), + }; + + let error = worker + .request_with_timeout(json!({"command": "never-reply"}), Duration::from_millis(10)) + .await; + assert!(error.unwrap_err().to_string().contains("timed out")); +} + #[cfg(unix)] fn shell_single_quote(path: &Path) -> String { path.to_string_lossy().replace('\'', "'\\''") diff --git a/crates/core/tests/unit/plugins/nemo_guardrails/remote_coverage_tests.rs b/crates/core/tests/unit/plugins/nemo_guardrails/remote_coverage_tests.rs index ac690c285..2e16c7bc6 100644 --- a/crates/core/tests/unit/plugins/nemo_guardrails/remote_coverage_tests.rs +++ b/crates/core/tests/unit/plugins/nemo_guardrails/remote_coverage_tests.rs @@ -14,6 +14,8 @@ use crate::plugins::nemo_guardrails::component::{RailSelector, RemoteBackendConf use tokio_stream::StreamExt; fn runtime_config(remote: RemoteBackendConfig) -> NeMoGuardrailsConfig { + let _ = spdlog::init_log_crate_proxy(); + log::set_max_level(log::LevelFilter::Info); NeMoGuardrailsConfig { remote: Some(remote), ..NeMoGuardrailsConfig::default() @@ -707,6 +709,7 @@ async fn remote_execute_reports_non_stream_success_http_errors_and_invalid_json( response["choices"][0]["message"]["content"], json!("guarded") ); + assert_eq!(success.access_state.load(Ordering::Acquire), 2); let invalid_json = runtime_with_endpoint(spawn_http_response( "200 OK", @@ -717,6 +720,7 @@ async fn remote_execute_reports_non_stream_success_http_errors_and_invalid_json( invalid_json.execute(simple_chat_request(), false).await, "failed to parse remote response JSON", ); + assert_eq!(invalid_json.access_state.load(Ordering::Acquire), 2); let http_error = runtime_with_endpoint(spawn_http_response( "502 Bad Gateway", @@ -727,6 +731,7 @@ async fn remote_execute_reports_non_stream_success_http_errors_and_invalid_json( http_error.execute(simple_chat_request(), false).await, "status 502", ); + assert_eq!(http_error.access_state.load(Ordering::Acquire), 1); } #[tokio::test] @@ -748,6 +753,7 @@ async fn remote_execute_transport_and_stream_status_errors_are_reported() { runtime.execute(simple_chat_request(), false).await, "remote request failed", ); + assert_eq!(runtime.access_state.load(Ordering::Acquire), 1); assert_flow_error_contains( runtime.execute_stream(simple_chat_request()).await, "remote stream request failed", @@ -1034,6 +1040,18 @@ async fn tool_remote_check_http_status_failures_are_reported() { .await, "status 503", ); + + let permission_error = runtime_with_endpoint(spawn_http_response( + "403 Forbidden", + "application/json", + r#"{"error":"forbidden"}"#, + )); + assert_flow_error_contains( + permission_error + .check_tool_input("weather_lookup", &json!({"city": "Phoenix"})) + .await, + "status 403", + ); } #[tokio::test] diff --git a/crates/core/tests/unit/shared_tests.rs b/crates/core/tests/unit/shared_tests.rs index d10e4f2e8..019f49bcb 100644 --- a/crates/core/tests/unit/shared_tests.rs +++ b/crates/core/tests/unit/shared_tests.rs @@ -72,6 +72,8 @@ fn lock_runtime_owner() -> std::sync::MutexGuard<'static, ()> { } fn reset_global() { + let _ = spdlog::init_log_crate_proxy(); + log::set_max_level(log::LevelFilter::Info); crate::shared_runtime::reset_runtime_owner_for_tests(); { let ctx = global_context(); @@ -147,6 +149,23 @@ fn test_resolve_parent_uuid_snapshot_and_runtime_owner_helpers() { reset_global(); } +#[test] +fn stale_process_runtime_owner_is_reclaimed() { + let _guard = lock_runtime_owner(); + reset_global(); + let stale_owner = format!( + "pid={};binding=rust;version={}", + std::process::id().saturating_add(1), + env!("CARGO_PKG_VERSION").split('.').next().unwrap() + ); + // SAFETY: The runtime-owner test mutex serializes this process-global test variable. + unsafe { std::env::set_var("NEMO_RELAY_RUNTIME_OWNER", stale_owner) }; + + ensure_runtime_owner().unwrap(); + + reset_global(); +} + #[test] fn test_run_request_intercepts_with_codec_none_and_codec_paths() { let _guard = lock_runtime_owner(); diff --git a/crates/pii-redaction/Cargo.toml b/crates/pii-redaction/Cargo.toml index 18d6eddfd..006a45b59 100644 --- a/crates/pii-redaction/Cargo.toml +++ b/crates/pii-redaction/Cargo.toml @@ -19,6 +19,7 @@ schema = ["dep:schemars", "nemo-relay/schema"] [dependencies] nemo-relay.workspace = true +log = { version = "0.4", features = ["kv"] } serde = { version = "1", features = ["derive"] } serde_json = "1" regex = "1" diff --git a/crates/pii-redaction/src/component.rs b/crates/pii-redaction/src/component.rs index 8c9322784..525a7d2e2 100644 --- a/crates/pii-redaction/src/component.rs +++ b/crates/pii-redaction/src/component.rs @@ -728,6 +728,13 @@ fn register_builtin_backend( PluginError::InvalidConfig("built-in PII redaction config is missing".to_string()) })?; let compiled = CompiledBuiltinBackend::new(builtin, config.codec.clone())?; + log::info!( + target: "nemo_relay.plugin", + event = "plugin_resource_validation_completed", + plugin_kind = PII_REDACTION_PLUGIN_KIND, + resource_count = 0; + "Plugin resource validation completed" + ); if config.mark { ctx.register_mark_sanitize_guardrail( diff --git a/crates/pii-redaction/src/local.rs b/crates/pii-redaction/src/local.rs index 12fbadb84..d76025596 100644 --- a/crates/pii-redaction/src/local.rs +++ b/crates/pii-redaction/src/local.rs @@ -44,10 +44,51 @@ pub(super) fn register_local_backend( ) -> PluginResult<()> { let provider = local_backend_provider_guard()?.clone(); - match provider { - Some(provider) => provider(config, ctx), - None => Err(PluginError::RegistrationFailed( + let Some(provider) = provider else { + log::warn!( + target: "nemo_relay.plugin", + event = "plugin_resource_access_failed", + plugin_kind = "pii_redaction", + resource_kind = "local_model_backend", + permission = "execute", + reason = "provider_unavailable"; + "Plugin resource access validation failed" + ); + return Err(PluginError::RegistrationFailed( "PII redaction local-model backend is unavailable in this runtime".to_string(), - )), + )); + }; + log::info!( + target: "nemo_relay.plugin", + event = "plugin_resource_access_pending", + plugin_kind = "pii_redaction", + resource_kind = "local_model_backend", + permission = "execute"; + "Plugin resource access validation started" + ); + match provider(config, ctx) { + Ok(()) => { + log::info!( + target: "nemo_relay.plugin", + event = "plugin_resource_access_validated", + plugin_kind = "pii_redaction", + resource_kind = "local_model_backend", + permission = "execute"; + "Plugin resource access validated" + ); + Ok(()) + } + Err(error) => { + log::warn!( + target: "nemo_relay.plugin", + event = "plugin_resource_access_failed", + plugin_kind = "pii_redaction", + resource_kind = "local_model_backend", + permission = "execute", + reason = "initialization_failed"; + "Plugin resource access validation failed" + ); + Err(error) + } } } diff --git a/crates/pii-redaction/tests/unit/component_tests.rs b/crates/pii-redaction/tests/unit/component_tests.rs index e0fc352d7..3b125c0e6 100644 --- a/crates/pii-redaction/tests/unit/component_tests.rs +++ b/crates/pii-redaction/tests/unit/component_tests.rs @@ -24,9 +24,9 @@ use crate::codec::openai_chat::OpenAIChatCodec; use crate::codec::openai_responses::OpenAIResponsesCodec; use crate::codec::traits::LlmResponseCodec; use crate::plugin::{ - PluginComponentSpec, PluginConfig, PluginRegistrationContext, clear_plugin_configuration, - ensure_builtin_plugins_registered, initialize_plugins, list_plugin_kinds, - validate_plugin_config, + PluginComponentSpec, PluginConfig, PluginError, PluginRegistrationContext, + clear_plugin_configuration, ensure_builtin_plugins_registered, initialize_plugins, + list_plugin_kinds, validate_plugin_config, }; use nemo_relay::observability::atif::{AtifAgentInfo, AtifExporter}; use nemo_relay::observability::atof::{AtofExporter, AtofExporterConfig}; @@ -37,8 +37,20 @@ use serde_json::json; use std::collections::BTreeMap; use std::sync::Arc; use std::sync::Mutex; +use std::sync::Once; use std::sync::atomic::{AtomicBool, Ordering}; +static TEST_LOGGING: Once = Once::new(); + +fn enable_operational_logs() { + TEST_LOGGING.call_once(|| { + let runtime = + nemo_relay::logging::init_logging(&nemo_relay::logging::LoggingConfig::default()) + .expect("test logging should initialize"); + Box::leak(Box::new(runtime)); + }); +} + fn component(config: Json) -> PluginComponentSpec { let Json::Object(config) = config else { panic!("component config must be an object"); @@ -59,6 +71,7 @@ fn plugin_config(config: Json) -> PluginConfig { } fn reset_runtime() { + enable_operational_logs(); let _ = clear_plugin_configuration(); crate::plugins::pii_redaction::component::clear_local_backend_provider().unwrap(); crate::shared_runtime::reset_runtime_owner_for_tests(); @@ -463,6 +476,37 @@ fn local_backend_provider_is_invoked_for_local_model_mode() { assert!(called.load(Ordering::SeqCst)); } +#[test] +fn local_backend_reports_missing_and_failed_provider_initialization() { + let _guard = crate::plugins::pii_redaction::test_mutex().lock().unwrap(); + reset_runtime(); + + let plugin = PiiRedactionPlugin; + let config = json!({"mode": "local_model"}); + let Json::Object(config) = config else { + panic!("component config must be object"); + }; + let mut ctx = PluginRegistrationContext::with_namespace("missing::"); + let missing = futures::executor::block_on(plugin.register(&config, &mut ctx)) + .expect_err("missing local provider should fail registration"); + assert!(missing.to_string().contains("unavailable")); + + register_local_backend_provider(Arc::new(|_, _| { + Err(PluginError::RegistrationFailed( + "provider initialization failed".into(), + )) + })) + .unwrap(); + let mut ctx = PluginRegistrationContext::with_namespace("failed::"); + let failed = futures::executor::block_on(plugin.register(&config, &mut ctx)) + .expect_err("failed local provider should fail registration"); + assert!( + failed + .to_string() + .contains("provider initialization failed") + ); +} + #[test] fn builtin_backend_sanitizes_mark_and_generic_scope_observability_fields() { let _guard = crate::plugins::pii_redaction::test_mutex().lock().unwrap();