Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
91 changes: 86 additions & 5 deletions crates/core/src/logging/mod.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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};
Expand All @@ -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<Option<LoggingRuntime>> = Mutex::new(None);
Comment thread
coderabbitai[bot] marked this conversation as resolved.
static ACTIVE_RELAY_LOGGER: Mutex<Option<Weak<Logger>>> = Mutex::new(None);

fn lock_logger_lifecycle() -> MutexGuard<'static, ()> {
LOGGER_LIFECYCLE_LOCK
Expand All @@ -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<Logger>) {
*ACTIVE_RELAY_LOGGER
.lock()
.unwrap_or_else(|error| error.into_inner()) = Some(Arc::downgrade(logger));
}

fn clear_active_relay_logger(logger: &Arc<Logger>) {
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(()),
Expand Down Expand Up @@ -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<Self> {
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<Self> {
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",
Expand Down Expand Up @@ -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);
}
}
}
Expand All @@ -170,6 +206,51 @@ pub fn init_logging(config: &LoggingConfig) -> Result<LoggingRuntime> {
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),
}
Comment thread
coderabbitai[bot] marked this conversation as resolved.
}
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;
115 changes: 114 additions & 1 deletion crates/core/tests/coverage/logging_tests.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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::<Value>(line).expect("valid JSONL lifecycle record"))
.collect::<Vec<_>>();
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
);
Comment thread
willkill07 marked this conversation as resolved.
}

#[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);
Comment thread
willkill07 marked this conversation as resolved.
}

#[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(&[
Expand Down Expand Up @@ -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;
}

Expand All @@ -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");

Expand Down
17 changes: 17 additions & 0 deletions crates/ffi/nemo_relay.h
Original file line number Diff line number Diff line change
Expand Up @@ -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.
*
Expand Down
29 changes: 29 additions & 0 deletions crates/ffi/src/api/mod.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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<T, F>(future: F) -> FlowResult<T>
where
T: Send,
Expand Down
13 changes: 13 additions & 0 deletions crates/ffi/tests/unit/api_tests.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Expand Down
Loading
Loading