diff --git a/crates/core/src/logging/mod.rs b/crates/core/src/logging/mod.rs index 9b3c7528c..4d06f5806 100644 --- a/crates/core/src/logging/mod.rs +++ b/crates/core/src/logging/mod.rs @@ -13,7 +13,7 @@ mod sink; use std::io::{self, Write}; use std::path::Path; -use std::sync::{Arc, Mutex, MutexGuard}; +use std::sync::{Arc, Mutex, MutexGuard, Weak}; use spdlog::sink::Sink; use spdlog::{Logger, ThreadPool}; @@ -33,6 +33,8 @@ use sink::log_level_filter; pub(crate) use format::format_event_for_test; static LOGGER_LIFECYCLE_LOCK: Mutex<()> = Mutex::new(()); +static DEFAULT_LOGGING_RUNTIME: Mutex> = Mutex::new(None); +static ACTIVE_RELAY_LOGGER: Mutex>> = Mutex::new(None); fn lock_logger_lifecycle() -> MutexGuard<'static, ()> { LOGGER_LIFECYCLE_LOCK @@ -44,6 +46,32 @@ fn log_crate_proxy_is_installed() -> bool { std::ptr::addr_eq(log::logger(), spdlog::log_crate_proxy() as &dyn log::Log) } +fn active_relay_logger_exists() -> bool { + ACTIVE_RELAY_LOGGER + .lock() + .unwrap_or_else(|error| error.into_inner()) + .as_ref() + .is_some_and(|logger| logger.upgrade().is_some()) +} + +fn set_active_relay_logger(logger: &Arc) { + *ACTIVE_RELAY_LOGGER + .lock() + .unwrap_or_else(|error| error.into_inner()) = Some(Arc::downgrade(logger)); +} + +fn clear_active_relay_logger(logger: &Arc) { + let mut active = ACTIVE_RELAY_LOGGER + .lock() + .unwrap_or_else(|error| error.into_inner()); + if active + .as_ref() + .is_some_and(|current| Weak::ptr_eq(current, &Arc::downgrade(logger))) + { + *active = None; + } +} + fn install_log_crate_proxy() -> Result<()> { match spdlog::init_log_crate_proxy() { Ok(()) => Ok(()), @@ -75,17 +103,22 @@ impl LoggingRuntime { /// opened. Dropping the returned runtime flushes sinks and detaches its logger from the /// process-global `log` proxy when it is still installed. pub fn configure(config: LoggingConfig) -> Result { - let root_relay_id = Uuid::now_v7().to_string(); - let (logger, thread_pools) = build_logger(&config, root_relay_id.clone())?; - // Install once per process. Subsequent calls (tests / re-entry) reuse the proxy and swap // the receiver logger. A different global logger would prevent Relay sinks from receiving // `log` facade records, so fail instead of returning a nonfunctional runtime. let _lifecycle = lock_logger_lifecycle(); + Self::configure_with_lifecycle_lock(config) + } + + fn configure_with_lifecycle_lock(config: LoggingConfig) -> Result { + let root_relay_id = Uuid::now_v7().to_string(); + let (logger, thread_pools) = build_logger(&config, root_relay_id.clone())?; + install_log_crate_proxy()?; spdlog::log_crate_proxy().set_logger(Some(Arc::clone(&logger))); spdlog::log_crate_proxy().set_filter(None); log::set_max_level(log_level_filter(config.level)); + set_active_relay_logger(&logger); log::info!( target: "nemo_relay.logging", @@ -154,7 +187,10 @@ impl Drop for LoggingRuntime { if let Some(logger) = detached && !Arc::ptr_eq(&logger, &self.logger) { - spdlog::log_crate_proxy().set_logger(Some(logger)); + spdlog::log_crate_proxy().set_logger(Some(Arc::clone(&logger))); + set_active_relay_logger(&logger); + } else { + clear_active_relay_logger(&self.logger); } } } @@ -170,6 +206,51 @@ pub fn init_logging(config: &LoggingConfig) -> Result { LoggingRuntime::configure(config.clone()) } +/// Installs and retains the default process-wide logging runtime for a language binding. +/// +/// Configuration is resolved from the supported logging environment variables, with built-in +/// defaults when none are present. Repeated initialization in the same linked runtime is a no-op. +#[doc(hidden)] +pub fn initialize_default_logging() -> Result<()> { + let mut runtime = DEFAULT_LOGGING_RUNTIME.lock().map_err(|error| { + FlowError::Internal(format!("default logging runtime lock poisoned: {error}")) + })?; + if runtime.is_none() { + let config = LoggingConfig::from_environment()?; + let uses_default_config = config.is_none(); + let _lifecycle = lock_logger_lifecycle(); + if uses_default_config && active_relay_logger_exists() { + return Ok(()); + } + match LoggingRuntime::configure_with_lifecycle_lock(config.unwrap_or_default()) { + Ok(configured) => *runtime = Some(configured), + // Language bindings initialize logging automatically. When Relay was not explicitly + // configured, defer to an application logger that already owns the process facade. + Err(FlowError::AlreadyExists(_)) if uses_default_config => {} + Err(error) => return Err(error), + } + } + Ok(()) +} + +/// Shuts down and releases the default process-wide logging runtime for a language binding. +/// +/// Repeated shutdown in the same linked runtime is a no-op. The runtime is removed from shared +/// state before its sinks are drained so shutdown does not hold the default-runtime lock. +#[doc(hidden)] +pub fn shutdown_default_logging() -> Result<()> { + let runtime = DEFAULT_LOGGING_RUNTIME + .lock() + .map_err(|error| { + FlowError::Internal(format!("default logging runtime lock poisoned: {error}")) + })? + .take(); + if let Some(runtime) = runtime { + runtime.shutdown(); + } + Ok(()) +} + #[cfg(test)] #[path = "../../tests/coverage/logging_tests.rs"] mod tests; diff --git a/crates/core/tests/coverage/logging_tests.rs b/crates/core/tests/coverage/logging_tests.rs index 430c4f3b6..6ecf30e6a 100644 --- a/crates/core/tests/coverage/logging_tests.rs +++ b/crates/core/tests/coverage/logging_tests.rs @@ -4,7 +4,7 @@ use crate::logging::{ FileLogRotationConfig, FileLogSinkConfig, LogFormat, LogLevel, LogSinkConfig, LoggingConfig, LoggingRuntime, MAX_FILE_SINK_QUEUE_ENTRIES, MAX_FILE_SINK_RETAINED_FILES, build_logger, - format_event_for_test, init_logging, + format_event_for_test, init_logging, initialize_default_logging, shutdown_default_logging, }; use opentelemetry::trace::{Span as _, Tracer as _, TracerProvider as _}; use opentelemetry_sdk::error::OTelSdkResult; @@ -192,6 +192,105 @@ queue_capacity = 16 assert_eq!(record["fields"]["source"], "toml"); } +#[test] +fn default_logging_runtime_initializes_once_and_shuts_down_idempotently() { + let temp = tempfile::tempdir().unwrap(); + let config_path = temp.path().join("logging.toml"); + let log_path = temp.path().join("relay.log.jsonl"); + std::fs::write( + &config_path, + format!( + r#" +[logging] +level = "info" +stderr_format = "human" +flush_interval_millis = 0 + +[[logging.sinks]] +path = {} +level = "info" +format = "jsonl" +queue_capacity = 16 +"#, + toml_basic_string(log_path.to_string_lossy().as_ref()) + ), + ) + .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())), + ]); + + shutdown_default_logging().unwrap(); + initialize_default_logging().unwrap(); + initialize_default_logging().unwrap(); + shutdown_default_logging().unwrap(); + shutdown_default_logging().unwrap(); + + let records = std::fs::read_to_string(log_path) + .unwrap() + .lines() + .map(|line| serde_json::from_str::(line).expect("valid JSONL lifecycle record")) + .collect::>(); + assert_eq!( + records + .iter() + .filter(|record| record["event"] == "logging_initialized") + .count(), + 1 + ); + assert_eq!( + records + .iter() + .filter(|record| record["event"] == "logging_shutdown_started") + .count(), + 1 + ); +} + +#[test] +fn implicit_default_logging_preserves_an_existing_relay_logger() { + let _environment = LoggingEnvScope::set(&[ + ("NEMO_RELAY_LOG", None), + ("NEMO_RELAY_LOG_STDERR_FORMAT", None), + ("NEMO_RELAY_LOG_CONFIG_PATH", None), + ]); + shutdown_default_logging().unwrap(); + let host_runtime = init_logging(&default_config()).unwrap(); + + initialize_default_logging().unwrap(); + shutdown_default_logging().unwrap(); + + let receiver = spdlog::log_crate_proxy().swap_logger(None); + let preserves_host_logger = receiver + .as_ref() + .is_some_and(|receiver| Arc::ptr_eq(receiver, &host_runtime.logger)); + spdlog::log_crate_proxy().set_logger(receiver); + assert!( + preserves_host_logger, + "implicit binding startup must preserve the host Relay logger" + ); + drop(host_runtime); +} + +#[test] +fn default_logging_runtime_rejects_invalid_environment() { + let _environment = LoggingEnvScope::set(&[ + ("NEMO_RELAY_LOG", Some(OsStr::new(""))), + ("NEMO_RELAY_LOG_STDERR_FORMAT", None), + ("NEMO_RELAY_LOG_CONFIG_PATH", None), + ]); + + shutdown_default_logging().unwrap(); + let error = initialize_default_logging().unwrap_err().to_string(); + + assert!( + error.contains("NEMO_RELAY_LOG must not be empty"), + "{error}" + ); +} + #[test] fn logging_config_from_environment_resolves_direct_settings() { let _environment = LoggingEnvScope::set(&[ @@ -1581,6 +1680,17 @@ fn configure_rejects_preinstalled_foreign_logger() { .contains("process-global log facade is already initialized by another logger"), "{error}" ); + initialize_default_logging() + .expect("unconfigured default logging should defer to the foreign logger"); + unsafe { std::env::set_var("NEMO_RELAY_LOG", "info") }; + let error = initialize_default_logging() + .expect_err("explicit default logging should reject the foreign logger"); + assert!( + error + .to_string() + .contains("process-global log facade is already initialized by another logger"), + "{error}" + ); return; } @@ -1589,6 +1699,9 @@ fn configure_rejects_preinstalled_foreign_logger() { let output = std::process::Command::new(std::env::current_exe().unwrap()) .args(["--exact", test_name, "--nocapture"]) .env(FOREIGN_LOGGER_CHILD_ENV, "1") + .env_remove("NEMO_RELAY_LOG") + .env_remove("NEMO_RELAY_LOG_STDERR_FORMAT") + .env_remove("NEMO_RELAY_LOG_CONFIG_PATH") .output() .expect("foreign logger child test should start"); diff --git a/crates/ffi/nemo_relay.h b/crates/ffi/nemo_relay.h index 9a17fe485..112286a8b 100644 --- a/crates/ffi/nemo_relay.h +++ b/crates/ffi/nemo_relay.h @@ -445,6 +445,23 @@ typedef char *(*NemoRelayToolExecInterceptCb)(void *user_data, */ typedef char *(*NemoRelayToolExecCb)(void *user_data, const char *args_json); +/** + * Initializes the Go binding runtime and installs default operational logging. + * + * Logging configuration is resolved from `NEMO_RELAY_LOG`, + * `NEMO_RELAY_LOG_STDERR_FORMAT`, or `NEMO_RELAY_LOG_CONFIG_PATH`, with built-in defaults when + * none are set. Repeated initialization is a no-op. + */ +NemoRelayStatus nemo_relay_initialize_default_logging(void); + +/** + * Shuts down and releases the default operational logging runtime. + * + * Pending file-sink records are drained before this function returns. Repeated shutdown is a + * no-op. + */ +NemoRelayStatus nemo_relay_shutdown_default_logging(void); + /** * Run the registered tool request intercept chain on the given arguments. * diff --git a/crates/ffi/src/api/mod.rs b/crates/ffi/src/api/mod.rs index cd08d8d03..848ad7243 100644 --- a/crates/ffi/src/api/mod.rs +++ b/crates/ffi/src/api/mod.rs @@ -99,6 +99,35 @@ fn tokio_runtime() -> &'static Runtime { }) } +/// Initializes the Go binding runtime and installs default operational logging. +/// +/// Logging configuration is resolved from `NEMO_RELAY_LOG`, +/// `NEMO_RELAY_LOG_STDERR_FORMAT`, or `NEMO_RELAY_LOG_CONFIG_PATH`, with built-in defaults when +/// none are set. Repeated initialization is a no-op. +#[unsafe(no_mangle)] +pub extern "C" fn nemo_relay_initialize_default_logging() -> NemoRelayStatus { + clear_last_error(); + let result = nemo_relay::shared_runtime::initialize_shared_runtime_binding("go") + .and_then(|()| nemo_relay::logging::initialize_default_logging()); + match result { + Ok(()) => NemoRelayStatus::Ok, + Err(error) => status_from_error(&error), + } +} + +/// Shuts down and releases the default operational logging runtime. +/// +/// Pending file-sink records are drained before this function returns. Repeated shutdown is a +/// no-op. +#[unsafe(no_mangle)] +pub extern "C" fn nemo_relay_shutdown_default_logging() -> NemoRelayStatus { + clear_last_error(); + match nemo_relay::logging::shutdown_default_logging() { + Ok(()) => NemoRelayStatus::Ok, + Err(error) => status_from_error(&error), + } +} + fn block_on_sync_ffi(future: F) -> FlowResult where T: Send, diff --git a/crates/ffi/tests/unit/api_tests.rs b/crates/ffi/tests/unit/api_tests.rs index 6f9eac085..e99c1b5ca 100644 --- a/crates/ffi/tests/unit/api_tests.rs +++ b/crates/ffi/tests/unit/api_tests.rs @@ -243,6 +243,19 @@ unsafe fn fresh_scope_stack() -> *mut FfiScopeStack { stack } +#[test] +fn default_logging_shutdown_is_idempotent() { + let _guard = lock_unpoisoned(&TEST_MUTEX); + assert_status!( + api::nemo_relay_shutdown_default_logging(), + NemoRelayStatus::Ok + ); + assert_status!( + api::nemo_relay_shutdown_default_logging(), + NemoRelayStatus::Ok + ); +} + #[test] fn propagation_context_json_round_trips_through_the_ffi() { let _guard = lock_unpoisoned(&TEST_MUTEX); diff --git a/crates/node/src/api/mod.rs b/crates/node/src/api/mod.rs index 9daec5dad..c81958ef8 100644 --- a/crates/node/src/api/mod.rs +++ b/crates/node/src/api/mod.rs @@ -16,7 +16,7 @@ use std::pin::Pin; use std::ptr; use std::sync::Arc; use std::sync::Mutex as StdMutex; -use std::sync::atomic::{AtomicBool, AtomicU64, Ordering}; +use std::sync::atomic::{AtomicBool, AtomicU64, AtomicUsize, Ordering}; use std::task::{Context, Poll}; use chrono::{DateTime, Utc}; @@ -88,6 +88,29 @@ use crate::promise_call::with_publication_callback_context; use crate::stream::LlmStream; use crate::types::{LlmHandle, ScopeHandle, ScopeStack, ScopeType, ToolHandle}; +static NODE_ENVIRONMENT_COUNT: AtomicUsize = AtomicUsize::new(0); +static NODE_ENVIRONMENT_LIFECYCLE_LOCK: StdMutex<()> = StdMutex::new(()); + +fn register_node_environment() -> FlowResult<()> { + let _guard = NODE_ENVIRONMENT_LIFECYCLE_LOCK + .lock() + .unwrap_or_else(|poisoned| poisoned.into_inner()); + nemo_relay::logging::initialize_default_logging()?; + NODE_ENVIRONMENT_COUNT.fetch_add(1, Ordering::AcqRel); + Ok(()) +} + +fn cleanup_node_environment() { + let _guard = NODE_ENVIRONMENT_LIFECYCLE_LOCK + .lock() + .unwrap_or_else(|poisoned| poisoned.into_inner()); + if NODE_ENVIRONMENT_COUNT.fetch_sub(1, Ordering::AcqRel) == 1 + && let Err(error) = nemo_relay::logging::shutdown_default_logging() + { + eprintln!("nemo-relay: operational logging shutdown failed: {error}"); + } +} + fn effective_scope_context( env: &Env, ) -> napi::Result<( @@ -127,7 +150,12 @@ fn init() { #[cfg(not(test))] #[napi_derive::module_exports] -fn install_well_known_symbol_methods(exports: JsObject, env: Env) -> napi::Result<()> { +fn install_well_known_symbol_methods(exports: JsObject, mut env: Env) -> napi::Result<()> { + register_node_environment().map_err(to_napi_err)?; + if let Err(error) = env.add_env_cleanup_hook((), |_| cleanup_node_environment()) { + cleanup_node_environment(); + return Err(error); + } let activation: JsFunction = exports.get_named_property("DynamicPluginActivation")?; let activation = activation.coerce_to_object()?; let mut prototype: JsObject = activation.get_named_property("prototype")?; diff --git a/crates/node/tests/logging_tests.mjs b/crates/node/tests/logging_tests.mjs new file mode 100644 index 000000000..2e4c8170b --- /dev/null +++ b/crates/node/tests/logging_tests.mjs @@ -0,0 +1,121 @@ +// SPDX-FileCopyrightText: Copyright (c) 2026, NVIDIA CORPORATION & AFFILIATES. All rights reserved. +// SPDX-License-Identifier: Apache-2.0 + +import { describe, it } from 'node:test'; +import assert from 'node:assert/strict'; +import { spawnSync } from 'node:child_process'; +import { mkdtempSync, readFileSync, rmSync, writeFileSync } from 'node:fs'; +import { tmpdir } from 'node:os'; +import { join } from 'node:path'; +import { fileURLToPath } from 'node:url'; + +const packageDirectory = fileURLToPath(new URL('..', import.meta.url)); +const loggingEnvironmentNames = ['NEMO_RELAY_LOG', 'NEMO_RELAY_LOG_STDERR_FORMAT', 'NEMO_RELAY_LOG_CONFIG_PATH']; + +function requireBinding(loggingEnvironment, source = "require('./index.js')") { + const environment = { ...process.env }; + for (const name of loggingEnvironmentNames) { + delete environment[name]; + } + Object.assign(environment, loggingEnvironment); + return spawnSync(process.execPath, ['-e', source], { + cwd: packageDirectory, + encoding: 'utf8', + env: environment, + }); +} + +describe('operational logging', () => { + it('initializes from the logging environment', () => { + const result = requireBinding({ + NEMO_RELAY_LOG: 'info', + NEMO_RELAY_LOG_STDERR_FORMAT: 'jsonl', + }); + + assert.equal(result.status, 0, result.stderr); + assert.match(result.stderr, /"event":"logging_initialized"/); + }); + + it('rejects an invalid logging environment', () => { + const result = requireBinding({ NEMO_RELAY_LOG: '' }); + + assert.notEqual(result.status, 0); + assert.match(result.stderr, /NEMO_RELAY_LOG must not be empty/); + }); + + it('flushes file sinks during environment cleanup', () => { + const directory = mkdtempSync(join(tmpdir(), 'nemo-relay-node-logging-')); + try { + const configPath = join(directory, 'logging.toml'); + const logPath = join(directory, 'operational.jsonl'); + writeFileSync( + configPath, + `[logging] +level = "info" +stderr_format = "human" +flush_interval_millis = 0 + +[[logging.sinks]] +path = ${JSON.stringify(logPath)} +level = "info" +format = "jsonl" +queue_capacity = 16 +`, + ); + + const result = requireBinding({ NEMO_RELAY_LOG_CONFIG_PATH: configPath }); + + assert.equal(result.status, 0, result.stderr); + assert.match(readFileSync(logPath, 'utf8'), /"event":"logging_shutdown_started"/); + } finally { + rmSync(directory, { recursive: true, force: true }); + } + }); + + it('keeps logging active while another Node environment remains', () => { + const directory = mkdtempSync(join(tmpdir(), 'nemo-relay-node-worker-logging-')); + try { + const configPath = join(directory, 'logging.toml'); + const logPath = join(directory, 'operational.jsonl'); + writeFileSync( + configPath, + `[logging] +level = "info" +stderr_format = "human" +flush_interval_millis = 0 + +[[logging.sinks]] +path = ${JSON.stringify(logPath)} +level = "info" +format = "jsonl" +queue_capacity = 16 +`, + ); + const workerSource = `require(${JSON.stringify(join(packageDirectory, 'index.js'))})`; + const source = ` +const { Worker } = require('node:worker_threads'); +const relay = require('./index.js'); +const worker = new Worker(${JSON.stringify(workerSource)}, { + eval: true, +}); +worker.once('error', (error) => { + console.error(error); + process.exitCode = 1; +}); +worker.once('exit', (code) => { + if (code !== 0) process.exitCode = code; + relay.deregisterPlugin('adaptive'); +}); +`; + + const result = requireBinding({ NEMO_RELAY_LOG_CONFIG_PATH: configPath }, source); + + assert.equal(result.status, 0, result.stderr); + const output = readFileSync(logPath, 'utf8'); + assert.match(output, /"event":"plugin_deregistered"/); + assert.match(output, /"event":"logging_shutdown_started"/); + } finally { + rmSync(directory, { recursive: true, force: true }); + } + }); +}); diff --git a/crates/python/src/lib.rs b/crates/python/src/lib.rs index 84ebb2295..a5f7ed04b 100644 --- a/crates/python/src/lib.rs +++ b/crates/python/src/lib.rs @@ -50,6 +50,11 @@ fn _native(m: &Bound<'_, PyModule>) -> PyResult<()> { "failed to initialize NeMo Relay runtime ownership: {e}" )) })?; + nemo_relay::logging::initialize_default_logging().map_err(|e| { + pyo3::exceptions::PyRuntimeError::new_err(format!( + "failed to initialize NeMo Relay operational logging: {e}" + )) + })?; register_adaptive_component().map_err(|e| { pyo3::exceptions::PyRuntimeError::new_err(format!( "failed to register adaptive plugin component: {e}" diff --git a/crates/python/src/py_api/mod.rs b/crates/python/src/py_api/mod.rs index d09933a0f..54f801702 100644 --- a/crates/python/src/py_api/mod.rs +++ b/crates/python/src/py_api/mod.rs @@ -62,6 +62,12 @@ fn to_py_err(e: FlowError) -> PyErr { PyErr::new::(e.to_string()) } +#[pyfunction(name = "_shutdown_default_logging")] +fn py_shutdown_default_logging(py: Python<'_>) -> PyResult<()> { + py.detach(nemo_relay::logging::shutdown_default_logging) + .map_err(to_py_err) +} + fn python_event_loop_running(py: Python<'_>) -> PyResult { match py.import("asyncio")?.call_method0("get_running_loop") { Ok(_) => Ok(true), @@ -2083,6 +2089,8 @@ fn scope_deregister_subscriber(scope_uuid: &str, name: &str) -> PyResult { /// Register all API functions into the given `PyModule`. pub fn register(m: &Bound<'_, PyModule>) -> PyResult<()> { + m.add_function(wrap_pyfunction!(py_shutdown_default_logging, m)?)?; + // Scope stack creation / binding / query m.add_function(wrap_pyfunction!(create_scope_stack, m)?)?; m.add_function(wrap_pyfunction!(capture_propagation_context, m)?)?; diff --git a/docs/reference/operational-logging.mdx b/docs/reference/operational-logging.mdx index 942a75149..c3912f29f 100644 --- a/docs/reference/operational-logging.mdx +++ b/docs/reference/operational-logging.mdx @@ -29,7 +29,7 @@ Use the source that matches how Relay is launched: | Use Case | Configuration Source | | --- | --- | | Run the Relay CLI with temporary settings | `--log-*` options | -| Configure a process without a Relay config file | `NEMO_RELAY_LOG*` environment variables | +| Configure a language binding or CLI process | `NEMO_RELAY_LOG*` environment variables | | Reuse logging settings across runs | `[logging]` in TOML | | Embed Relay in a Rust application | `LoggingConfig` and `LoggingRuntime` | @@ -40,8 +40,10 @@ For CLI processes, Relay selects one source in this order: 3. `[logging]` in the resolved Relay `config.toml` 4. Built-in defaults -Sources are selected rather than merged. Rust applications explicitly choose -which `LoggingRuntime` initialization method to use and do not apply the CLI +Sources are selected rather than merged. Python, Node.js, and Go install a +process-lifetime `LoggingRuntime` when the binding loads, using environment +configuration or built-in defaults. Rust applications explicitly choose which +`LoggingRuntime` initialization method to use and do not apply the CLI precedence rules. ## CLI Options @@ -63,8 +65,9 @@ Do not combine `--log-config-path` with `--log-level` or ## Environment Variables -Set these variables for the CLI or a Rust application that initializes logging -with `LoggingRuntime::configure_from_environment()`: +Set these variables for a Python, Node.js, or Go process, the CLI, or a Rust +application that initializes logging with +`LoggingRuntime::configure_from_environment()`: ```bash export NEMO_RELAY_LOG=debug @@ -85,6 +88,22 @@ export NEMO_RELAY_LOG_CONFIG_PATH=/absolute/path/to/logging.toml `NEMO_RELAY_LOG_CONFIG_PATH` cannot be combined with the other logging environment variables. +When none of these variables are set, Python, Node.js, and Go install Relay's +built-in default logger unless the host already owns Rust's process-global +`log` facade. They also preserve an existing Relay logger rather than replacing +it. Records emitted before any logger is installed are discarded, and a host +cannot install its own logger after Relay has claimed the facade. Set one of +these variables when Relay must configure its own logging. + +This binding behavior differs from +`LoggingRuntime::configure_from_environment()`, which always attempts to +install Relay's built-in defaults when no variables are set. + +Python and Node.js drain pending file-sink records during normal runtime +teardown. Go applications that configure file sinks must call +`nemo_relay.ShutdownLogging` before `main` returns; defer it near the start of +`main` so it runs after other Relay cleanup. + ## TOML Configuration Logging settings use a `[logging]` table: diff --git a/go/nemo_relay/README.md b/go/nemo_relay/README.md index 57bbca94c..5162c1bf9 100644 --- a/go/nemo_relay/README.md +++ b/go/nemo_relay/README.md @@ -110,6 +110,12 @@ import ( ) func main() { + defer func() { + if err := nemo.ShutdownLogging(); err != nil { + log.Printf("shut down NeMo Relay logging: %v", err) + } + }() + if err := nemo.RegisterSubscriber("printer", func(event nemo.Event) { fmt.Printf("%s %s\n", event.Kind(), event.Name()) fmt.Println(string(event.JSON())) diff --git a/go/nemo_relay/logging_test.go b/go/nemo_relay/logging_test.go new file mode 100644 index 000000000..09af8e799 --- /dev/null +++ b/go/nemo_relay/logging_test.go @@ -0,0 +1,111 @@ +// SPDX-FileCopyrightText: Copyright (c) 2026, NVIDIA CORPORATION & AFFILIATES. All rights reserved. +// SPDX-License-Identifier: Apache-2.0 + +package nemo_relay + +import ( + "os" + "os/exec" + "path/filepath" + "strconv" + "strings" + "testing" +) + +const loggingHelperEnvironment = "NEMO_RELAY_TEST_LOGGING_HELPER" + +var loggingEnvironmentNames = map[string]struct{}{ + "NEMO_RELAY_LOG": {}, + "NEMO_RELAY_LOG_STDERR_FORMAT": {}, + "NEMO_RELAY_LOG_CONFIG_PATH": {}, +} + +func loggingTestEnvironment(values ...string) []string { + environment := make([]string, 0, len(os.Environ())+len(values)) + for _, value := range os.Environ() { + name, _, _ := strings.Cut(value, "=") + if _, isLoggingEnvironment := loggingEnvironmentNames[name]; !isLoggingEnvironment { + environment = append(environment, value) + } + } + return append(environment, values...) +} + +func TestBindingLoggingEnvironment(t *testing.T) { + if helper := os.Getenv(loggingHelperEnvironment); helper != "" { + if helper == "shutdown" { + if err := ShutdownLogging(); err != nil { + t.Fatalf("logging shutdown failed: %v", err) + } + } + return + } + + t.Run("initializes from environment", func(t *testing.T) { + command := exec.Command(os.Args[0], "-test.run=TestBindingLoggingEnvironment") + command.Env = loggingTestEnvironment( + loggingHelperEnvironment+"=shutdown", + "NEMO_RELAY_LOG=info", + "NEMO_RELAY_LOG_STDERR_FORMAT=jsonl", + ) + output, err := command.CombinedOutput() + if err != nil { + t.Fatalf("binding import failed: %v\n%s", err, output) + } + if !strings.Contains(string(output), `"event":"logging_initialized"`) { + t.Fatalf("logging initialization event missing from output:\n%s", output) + } + }) + + t.Run("rejects invalid environment", func(t *testing.T) { + command := exec.Command(os.Args[0], "-test.run=TestBindingLoggingEnvironment") + command.Env = loggingTestEnvironment( + loggingHelperEnvironment+"=1", + "NEMO_RELAY_LOG=", + ) + output, err := command.CombinedOutput() + if err == nil { + t.Fatalf("binding initialization unexpectedly succeeded:\n%s", output) + } + if !strings.Contains(string(output), "NEMO_RELAY_LOG must not be empty") { + t.Fatalf("logging initialization error missing from output:\n%s", output) + } + }) + + t.Run("flushes file sink during shutdown", func(t *testing.T) { + directory := t.TempDir() + configPath := filepath.Join(directory, "logging.toml") + logPath := filepath.Join(directory, "operational.jsonl") + config := `[logging] +level = "info" +stderr_format = "human" +flush_interval_millis = 0 + +[[logging.sinks]] +path = ` + strconv.Quote(logPath) + ` +level = "info" +format = "jsonl" +queue_capacity = 16 +` + if err := os.WriteFile(configPath, []byte(config), 0o600); err != nil { + t.Fatalf("write logging config: %v", err) + } + + command := exec.Command(os.Args[0], "-test.run=TestBindingLoggingEnvironment") + command.Env = loggingTestEnvironment( + loggingHelperEnvironment+"=shutdown", + "NEMO_RELAY_LOG_CONFIG_PATH="+configPath, + ) + output, err := command.CombinedOutput() + if err != nil { + t.Fatalf("binding logging shutdown failed: %v\n%s", err, output) + } + contents, err := os.ReadFile(logPath) + if err != nil { + t.Fatalf("read operational log: %v", err) + } + if !strings.Contains(string(contents), `"event":"logging_shutdown_started"`) { + t.Fatalf("logging shutdown event missing from file:\n%s", contents) + } + }) +} diff --git a/go/nemo_relay/nemo_relay.go b/go/nemo_relay/nemo_relay.go index 3046120f5..8646c122a 100644 --- a/go/nemo_relay/nemo_relay.go +++ b/go/nemo_relay/nemo_relay.go @@ -46,6 +46,8 @@ typedef struct NemoRelayLlmSanitizeResponseContext { uint32_t codec_kind; const typedef void (*NemoRelayFreeFn)(void* user_data); // Core API +extern int32_t nemo_relay_initialize_default_logging(void); +extern int32_t nemo_relay_shutdown_default_logging(void); extern int32_t nemo_relay_get_handle(FfiScopeHandle** out); extern int32_t nemo_relay_push_scope(const char* name, int32_t scope_type, const FfiScopeHandle* parent, uint32_t attributes, const char* data_json, const char* metadata_json, const char* input_json, const int64_t* timestamp_unix_micros, FfiScopeHandle** out); extern int32_t nemo_relay_pop_scope(const FfiScopeHandle* handle, const char* output_json, const char* metadata_json, const int64_t* timestamp_unix_micros); @@ -298,6 +300,18 @@ import ( const defaultServiceName = "nemo-relay" +func init() { + if err := checkStatus(C.nemo_relay_initialize_default_logging()); err != nil { + panic(fmt.Sprintf("failed to initialize NeMo Relay operational logging: %v", err)) + } +} + +// ShutdownLogging drains pending operational log records and releases the default logging runtime. +// Callers that configure file sinks should defer ShutdownLogging from main. +func ShutdownLogging() error { + return checkStatus(C.nemo_relay_shutdown_default_logging()) +} + func checkedValue[T any](status int32, value T) (T, error) { if err := checkStatus(C.int32_t(status)); err != nil { var zero T diff --git a/python/nemo_relay/__init__.py b/python/nemo_relay/__init__.py index 585fbe683..1fa187220 100644 --- a/python/nemo_relay/__init__.py +++ b/python/nemo_relay/__init__.py @@ -77,6 +77,7 @@ async def main(): from __future__ import annotations +import atexit import contextvars import typing from collections.abc import Callable as AbcCallable @@ -119,6 +120,7 @@ async def main(): ToolAttributes, ToolExecutionInterceptOutcome, ToolHandle, + _shutdown_default_logging, ) from nemo_relay._native import ( capture_propagation_context as _capture_propagation_context, @@ -136,6 +138,8 @@ async def main(): from nemo_relay._native import set_thread_scope_stack as _set_thread_scope_stack from nemo_relay._native import sync_thread_scope_stack as _sync_thread_scope_stack +atexit.register(_shutdown_default_logging) + #: Scalar JSON leaf values accepted in NeMo Relay payloads. This alias has no #: runtime behavior; it exists to document and type JSON-compatible public API #: arguments and return values. diff --git a/python/nemo_relay/_native.pyi b/python/nemo_relay/_native.pyi index 43f2fa5f1..cc025751c 100644 --- a/python/nemo_relay/_native.pyi +++ b/python/nemo_relay/_native.pyi @@ -32,6 +32,8 @@ _JsonObject: TypeAlias = dict[str, _JsonValue] _Json: TypeAlias = _JsonValue _MessageContent: TypeAlias = str | Sequence[Mapping[str, _JsonValue]] +def _shutdown_default_logging() -> None: ... + class _EventSanitizeFields(TypedDict): data: _Json | None category_profile: _JsonObject | None diff --git a/python/tests/test_logging.py b/python/tests/test_logging.py new file mode 100644 index 000000000..9312a7ac9 --- /dev/null +++ b/python/tests/test_logging.py @@ -0,0 +1,67 @@ +# SPDX-FileCopyrightText: Copyright (c) 2026, NVIDIA CORPORATION & AFFILIATES. All rights reserved. +# SPDX-License-Identifier: Apache-2.0 + +import json +import os +import subprocess +import sys + +_LOG_ENVIRONMENT = ( + "NEMO_RELAY_LOG", + "NEMO_RELAY_LOG_STDERR_FORMAT", + "NEMO_RELAY_LOG_CONFIG_PATH", +) + + +def _import_nemo_relay(**logging_environment: str) -> subprocess.CompletedProcess[str]: + environment = os.environ.copy() + for name in _LOG_ENVIRONMENT: + environment.pop(name, None) + environment.update(logging_environment) + return subprocess.run( + [sys.executable, "-c", "import nemo_relay"], + check=False, + capture_output=True, + text=True, + env=environment, + ) + + +def test_binding_initializes_logging_from_environment(): + completed = _import_nemo_relay( + NEMO_RELAY_LOG="info", + NEMO_RELAY_LOG_STDERR_FORMAT="jsonl", + ) + + assert completed.returncode == 0, completed.stderr + assert '"event":"logging_initialized"' in completed.stderr + + +def test_binding_rejects_invalid_logging_environment(): + completed = _import_nemo_relay(NEMO_RELAY_LOG="") + + assert completed.returncode != 0 + assert "NEMO_RELAY_LOG must not be empty" in completed.stderr + + +def test_binding_flushes_file_sink_during_shutdown(tmp_path): + config_path = tmp_path / "logging.toml" + log_path = tmp_path / "operational.jsonl" + config_path.write_text( + f"""[logging] +level = "info" +stderr_format = "human" +flush_interval_millis = 0 + +[[logging.sinks]] +path = {json.dumps(str(log_path))} +level = "info" +format = "jsonl" +queue_capacity = 16 +""" + ) + + completed = _import_nemo_relay(NEMO_RELAY_LOG_CONFIG_PATH=str(config_path)) + + assert completed.returncode == 0, completed.stderr + assert '"event":"logging_shutdown_started"' in log_path.read_text()