Complete first release candidate audit (#107)

crates/libremetaverse/src/logger.rs

@@ -0,0 +1,655 @@
+//! Process-wide logging facade and callback compatibility layer.
+
+use std::any::Any;
+use std::collections::{BTreeMap, HashMap};
+use std::fmt;
+use std::sync::{
+    Arc, Mutex, OnceLock,
+    atomic::{AtomicBool, AtomicU64, Ordering},
+};
+use std::thread::ThreadId;
+use std::time::Duration;
+
+use libremetaverse_types::compat::{
+    CancellationToken, Close, ExternalError, Object, Subscription, Task, TaskCompletionSource,
+};
+
+use crate::callback_runtime::AsyncInvocation;
+use crate::logging::{ILogger, ILoggerFactory, LogLevel};
+use crate::{Error, GridClient, Settings, Simulator};
+
+struct LoggerState {
+    factory: Option<Arc<dyn ILoggerFactory>>,
+    logger: Option<Arc<dyn ILogger>>,
+    callbacks: BTreeMap<u64, LoggerLogCallback>,
+    next_callback: u64,
+}
+
+impl Default for LoggerState {
+    fn default() -> Self {
+        Self {
+            factory: None,
+            logger: None,
+            callbacks: BTreeMap::new(),
+            next_callback: 1,
+        }
+    }
+}
+
+fn state() -> &'static Mutex<LoggerState> {
+    static STATE: OnceLock<Mutex<LoggerState>> = OnceLock::new();
+    STATE.get_or_init(|| Mutex::new(LoggerState::default()))
+}
+
+fn ensure_initialized() -> Arc<dyn ILogger> {
+    let mut state = state()
+        .lock()
+        .unwrap_or_else(std::sync::PoisonError::into_inner);
+    if let Some(logger) = state.logger.as_ref() {
+        return Arc::clone(logger);
+    }
+    let factory: Arc<dyn ILoggerFactory> = Arc::new(ConsoleLoggerFactory::default());
+    let logger = factory.create_logger("LibreMetaverse.Logger");
+    state.factory = Some(factory);
+    state.logger = Some(Arc::clone(&logger));
+    logger
+}
+
+#[derive(Default)]
+struct ConsoleLoggerFactory {
+    closed: Arc<AtomicBool>,
+}
+
+impl ILoggerFactory for ConsoleLoggerFactory {
+    fn create_logger(&self, name: &str) -> Arc<dyn ILogger> {
+        Arc::new(ConsoleLogger {
+            name: name.to_owned(),
+            closed: Arc::clone(&self.closed),
+            scopes: Arc::new(Mutex::new(HashMap::new())),
+            next_scope: Arc::new(AtomicU64::new(1)),
+        })
+    }
+
+    fn shutdown(&self) -> Result<(), ExternalError> {
+        self.closed.store(true, Ordering::Release);
+        Ok(())
+    }
+}
+
+type ScopeMap = HashMap<ThreadId, Vec<(u64, Object)>>;
+
+struct ConsoleLogger {
+    name: String,
+    closed: Arc<AtomicBool>,
+    scopes: Arc<Mutex<ScopeMap>>,
+    next_scope: Arc<AtomicU64>,
+}
+
+impl ILogger for ConsoleLogger {
+    fn is_enabled(&self, level: LogLevel) -> bool {
+        !self.closed.load(Ordering::Acquire) && level != LogLevel::NONE && level >= LogLevel::DEBUG
+    }
+
+    fn log(
+        &self,
+        level: LogLevel,
+        message: &Object,
+        exception: Option<&ExternalError>,
+        client_name: Option<&str>,
+    ) {
+        if !self.is_enabled(level) {
+            return;
+        }
+        let scopes = self
+            .scopes
+            .lock()
+            .unwrap_or_else(std::sync::PoisonError::into_inner)
+            .get(&std::thread::current().id())
+            .cloned()
+            .unwrap_or_default();
+        let scope_text = scopes
+            .iter()
+            .map(|(_, state)| format!("{state:?}"))
+            .collect::<Vec<_>>()
+            .join(" ");
+        let level_name = match level {
+            LogLevel::TRACE => "TRACE",
+            LogLevel::DEBUG => "DEBUG",
+            LogLevel::INFORMATION => "INFO",
+            LogLevel::WARNING => "WARN",
+            LogLevel::ERROR => "ERROR",
+            LogLevel::CRITICAL => "CRITICAL",
+            _ => "LOG",
+        };
+        let client = client_name
+            .filter(|name| !name.is_empty())
+            .map_or(String::new(), |name| format!(" [{name}]"));
+        let scope = if scope_text.is_empty() {
+            String::new()
+        } else {
+            format!(" [{scope_text}]")
+        };
+        let exception = exception.map_or(String::new(), |error| format!(": {}", error.0));
+        eprintln!(
+            "[{level_name}] [{}]{client}{scope} {message:?}{exception}",
+            self.name
+        );
+    }
+
+    fn begin_scope(&self, state: Object) -> Box<dyn Close> {
+        let thread_id = std::thread::current().id();
+        let id = self.next_scope.fetch_add(1, Ordering::Relaxed);
+        self.scopes
+            .lock()
+            .unwrap_or_else(std::sync::PoisonError::into_inner)
+            .entry(thread_id)
+            .or_default()
+            .push((id, state));
+        Box::new(ConsoleScope {
+            scopes: Arc::clone(&self.scopes),
+            thread_id,
+            id: Some(id),
+        })
+    }
+}
+
+struct ConsoleScope {
+    scopes: Arc<Mutex<ScopeMap>>,
+    thread_id: ThreadId,
+    id: Option<u64>,
+}
+
+impl Close for ConsoleScope {
+    fn close(&mut self) -> Result<(), ExternalError> {
+        let Some(id) = self.id.take() else {
+            return Ok(());
+        };
+        let mut scopes = self
+            .scopes
+            .lock()
+            .unwrap_or_else(std::sync::PoisonError::into_inner);
+        if let Some(thread_scopes) = scopes.get_mut(&self.thread_id) {
+            thread_scopes.retain(|(scope_id, _)| *scope_id != id);
+            if thread_scopes.is_empty() {
+                scopes.remove(&self.thread_id);
+            }
+        }
+        Ok(())
+    }
+}
+
+impl Drop for ConsoleScope {
+    fn drop(&mut self) {
+        let _ = self.close();
+    }
+}
+
+struct NoopScope;
+
+impl Close for NoopScope {
+    fn close(&mut self) -> Result<(), ExternalError> {
+        Ok(())
+    }
+}
+
+type LogHandler = Arc<dyn Fn(Object, LogLevel) + Send + Sync>;
+
+pub struct LoggerCallbackTarget(pub LogHandler);
+
+impl fmt::Debug for LoggerCallbackTarget {
+    fn fmt(&self, formatter: &mut fmt::Formatter<'_>) -> fmt::Result {
+        formatter.write_str("LoggerCallbackTarget(..)")
+    }
+}
+
+#[derive(Clone)]
+pub struct LoggerLogCallback(LogHandler);
+
+impl LoggerLogCallback {
+    pub fn from_callback(callback: impl Fn(Object, LogLevel) + Send + Sync + 'static) -> Self {
+        Self(Arc::new(callback))
+    }
+
+    pub fn new(object: Object, method: isize) -> Result<Self, Error> {
+        if method != 0 {
+            return Err(Error::Argument);
+        }
+        object
+            .downcast_arc::<LoggerCallbackTarget>()
+            .map(|target| Self(Arc::clone(&target.0)))
+            .ok_or(Error::Argument)
+    }
+
+    pub fn begin_invoke(
+        &self,
+        message: Object,
+        level: LogLevel,
+        callback: Box<dyn Fn(&dyn Any) + Send + Sync>,
+        object: Object,
+    ) -> Result<Box<dyn Any + Send + Sync>, Error> {
+        let invocation = AsyncInvocation::pending(object);
+        let worker_invocation = invocation.clone();
+        let handler = Arc::clone(&self.0);
+        std::thread::Builder::new()
+            .name("logger-callback".to_owned())
+            .spawn(move || {
+                let result = std::panic::catch_unwind(std::panic::AssertUnwindSafe(|| {
+                    handler(message, level);
+                }))
+                .map_err(|_| Error::InvalidOperation);
+                worker_invocation.complete(result);
+                let _ = std::panic::catch_unwind(std::panic::AssertUnwindSafe(|| {
+                    callback(&worker_invocation);
+                }));
+            })
+            .map_err(|_| Error::InvalidOperation)?;
+        Ok(Box::new(invocation))
+    }
+
+    pub fn end_invoke(&self, result: Box<dyn Any + Send + Sync>) -> Result<(), Error> {
+        result
+            .downcast::<AsyncInvocation>()
+            .map_err(|_| Error::Argument)?
+            .wait()
+    }
+
+    pub fn invoke(&self, message: Object, level: LogLevel) -> Result<(), Error> {
+        (self.0)(message, level);
+        Ok(())
+    }
+}
+
+pub struct Logger;
+
+impl Logger {
+    pub fn subscribe_on_log_message(handler: Option<LoggerLogCallback>) -> Subscription {
+        let Some(handler) = handler else {
+            return Subscription::detached();
+        };
+        let id = {
+            let mut state = state()
+                .lock()
+                .unwrap_or_else(std::sync::PoisonError::into_inner);
+            let id = state.next_callback;
+            state.next_callback = state.next_callback.wrapping_add(1).max(1);
+            state.callbacks.insert(id, handler);
+            id
+        };
+        Subscription::new(move || {
+            state()
+                .lock()
+                .unwrap_or_else(std::sync::PoisonError::into_inner)
+                .callbacks
+                .remove(&id);
+        })
+    }
+
+    pub fn begin_scope(state_value: Object) -> Result<Box<dyn Close>, Error> {
+        let logger = state()
+            .lock()
+            .unwrap_or_else(std::sync::PoisonError::into_inner)
+            .logger
+            .clone();
+        Ok(logger.map_or_else(
+            || Box::new(NoopScope) as Box<dyn Close>,
+            |logger| logger.begin_scope(state_value),
+        ))
+    }
+
+    pub fn begin_client_scope(mut client: GridClient) -> Result<Box<dyn Close>, Error> {
+        let log_names = client.settings().logging.log_names;
+        if !log_names {
+            return Ok(Box::new(NoopScope));
+        }
+        let name = client.self_().name();
+        if name.is_empty() {
+            return Ok(Box::new(NoopScope));
+        }
+        Self::begin_scope(Object::Map(HashMap::from([(
+            "Client".to_owned(),
+            Object::String(name),
+        )])))
+    }
+
+    pub fn begin_region_scope(simulator: Simulator) -> Result<Box<dyn Close>, Error> {
+        let name = if simulator.name.is_empty() {
+            simulator.handle.to_string()
+        } else {
+            simulator.name.clone()
+        };
+        Self::begin_scope(Object::Map(HashMap::from([(
+            "Region".to_owned(),
+            Object::String(name),
+        )])))
+    }
+
+    pub fn create_default_console_logger_factory() -> Result<Box<dyn ILoggerFactory>, Error> {
+        Ok(Box::new(ConsoleLoggerFactory::default()))
+    }
+
+    pub fn set_logger_factory(factory: Box<dyn ILoggerFactory>, name: String) -> Result<(), Error> {
+        let factory: Arc<dyn ILoggerFactory> = Arc::from(factory);
+        let logger = factory.create_logger(&name);
+        let previous = {
+            let mut state = state()
+                .lock()
+                .unwrap_or_else(std::sync::PoisonError::into_inner);
+            let previous = state.factory.replace(Arc::clone(&factory));
+            state.logger = Some(logger);
+            previous
+        };
+        if let Some(previous) = previous {
+            let _ = previous.shutdown();
+        }
+        Ok(())
+    }
+
+    pub fn shutdown_with_method() -> Result<(), Error> {
+        let factory = {
+            let mut state = state()
+                .lock()
+                .unwrap_or_else(std::sync::PoisonError::into_inner);
+            state.logger = None;
+            state.factory.take()
+        };
+        if let Some(factory) = factory {
+            let _ = factory.shutdown();
+        }
+        Ok(())
+    }
+
+    pub async fn shutdown_with_nullable_cancellation_token(
+        timeout: Option<Option<Duration>>,
+        cancellation_token: Option<CancellationToken>,
+    ) -> Result<bool, Error> {
+        let factory = {
+            let mut state = state()
+                .lock()
+                .unwrap_or_else(std::sync::PoisonError::into_inner);
+            state.logger = None;
+            state.factory.take()
+        };
+        let Some(factory) = factory else {
+            return Ok(true);
+        };
+        let completion = TaskCompletionSource::new();
+        let shutdown_completion = completion.clone();
+        if std::thread::Builder::new()
+            .name("logger-shutdown".to_owned())
+            .spawn(move || {
+                let _ = shutdown_completion.try_set_result(factory.shutdown().is_ok());
+            })
+            .is_err()
+        {
+            return Ok(false);
+        }
+        let cancellation = cancellation_token.map(|token| {
+            let completion = completion.clone();
+            token.register_callback(Arc::new(move || {
+                let _ = completion.try_set_result(false);
+            }))
+        });
+        if let Some(timeout) = timeout.flatten() {
+            let timeout_completion = completion.clone();
+            let _ = std::thread::Builder::new()
+                .name("logger-shutdown-timeout".to_owned())
+                .spawn(move || {
+                    std::thread::sleep(timeout);
+                    let _ = timeout_completion.try_set_result(false);
+                });
+        }
+        let result = completion.future().await;
+        drop(cancellation);
+        result
+    }
+
+    fn callbacks() -> Vec<LoggerLogCallback> {
+        state()
+            .lock()
+            .unwrap_or_else(std::sync::PoisonError::into_inner)
+            .callbacks
+            .values()
+            .cloned()
+            .collect()
+    }
+
+    fn raise(message: &Object, level: LogLevel) {
+        for callback in Self::callbacks() {
+            let message = message.clone();
+            let _ = std::thread::Builder::new()
+                .name("logger-event".to_owned())
+                .spawn(move || {
+                    let _ = std::panic::catch_unwind(std::panic::AssertUnwindSafe(|| {
+                        let _ = callback.invoke(message, level);
+                    }));
+                });
+        }
+    }
+
+    fn client_name(mut client: Option<GridClient>) -> Option<String> {
+        let client = client.as_mut()?;
+        if !client.settings().logging.log_names {
+            return None;
+        }
+        let name = client.self_().name();
+        (!name.is_empty()).then_some(name)
+    }
+
+    fn log_to_sink(
+        message: &Object,
+        level: LogLevel,
+        exception: Option<&ExternalError>,
+        client_name: Option<&str>,
+    ) {
+        let logger = ensure_initialized();
+        if logger.is_enabled(level) {
+            logger.log(level, message, exception, client_name);
+        }
+    }
+
+    fn log(
+        message: Object,
+        level: LogLevel,
+        client: Option<GridClient>,
+        exception: Option<ExternalError>,
+    ) -> Result<(), Error> {
+        Self::raise(&message, level);
+        let configured = Settings::log_level();
+        if configured == LogLevel::NONE || configured > level {
+            return Ok(());
+        }
+        let client_name = Self::client_name(client);
+        Self::log_to_sink(&message, level, exception.as_ref(), client_name.as_deref());
+        Ok(())
+    }
+
+    fn log_named(
+        message: Object,
+        level: LogLevel,
+        exception: Option<ExternalError>,
+        client_name: String,
+    ) -> Result<(), Error> {
+        Self::log_to_sink(&message, level, exception.as_ref(), Some(&client_name));
+        Ok(())
+    }
+
+    pub fn is_enabled(level: LogLevel) -> Result<bool, Error> {
+        Ok(ensure_initialized().is_enabled(level))
+    }
+
+    pub fn log_with_object_log_level_grid_client(
+        message: Object,
+        level: LogLevel,
+        client: Option<GridClient>,
+    ) -> Result<(), Error> {
+        Self::log(message, level, client, None)
+    }
+
+    pub fn log_with_object_log_level_grid_client_exception(
+        message: Object,
+        level: LogLevel,
+        client: Option<GridClient>,
+        exception: Option<ExternalError>,
+    ) -> Result<(), Error> {
+        Self::log(message, level, client, exception)
+    }
+
+    pub fn log_with_object_log_level_exception(
+        message: Object,
+        level: LogLevel,
+        exception: ExternalError,
+    ) -> Result<(), Error> {
+        Self::log(message, level, None, Some(exception))
+    }
+
+    pub fn debug_log(message: Object, client: Option<GridClient>) -> Result<(), Error> {
+        let level = Settings::log_level();
+        if level > LogLevel::DEBUG {
+            return Ok(());
+        }
+        Self::log(message, level, client, None)
+    }
+
+    pub async fn use_scope(
+        state: Object,
+        action: Box<dyn Fn() -> Task<()> + Send + Sync>,
+    ) -> Result<(), Error> {
+        let mut scope = Self::begin_scope(state)?;
+        let result = action().await;
+        let close = scope.close().map_err(|_| Error::InvalidOperation);
+        result.and(close)
+    }
+
+    pub async fn use_client_scope(
+        client: GridClient,
+        action: Box<dyn Fn() -> Task<()> + Send + Sync>,
+    ) -> Result<(), Error> {
+        let mut scope = Self::begin_client_scope(client)?;
+        let result = action().await;
+        let close = scope.close().map_err(|_| Error::InvalidOperation);
+        result.and(close)
+    }
+
+    pub async fn use_region_scope(
+        simulator: Simulator,
+        action: Box<dyn Fn() -> Task<()> + Send + Sync>,
+    ) -> Result<(), Error> {
+        let mut scope = Self::begin_region_scope(simulator)?;
+        let result = action().await;
+        let close = scope.close().map_err(|_| Error::InvalidOperation);
+        result.and(close)
+    }
+}
+
+macro_rules! level_methods {
+    ($client:ident, $client_error:ident, $named:ident, $named_error:ident, $level:expr) => {
+        impl Logger {
+            pub fn $client(message: Object, client: Option<GridClient>) -> Result<(), Error> {
+                Self::log(message, $level, client, None)
+            }
+
+            pub fn $client_error(
+                message: Object,
+                exception: ExternalError,
+                client: Option<GridClient>,
+            ) -> Result<(), Error> {
+                Self::log(message, $level, client, Some(exception))
+            }
+
+            pub fn $named(message: Object, client_name: String) -> Result<(), Error> {
+                Self::log_named(message, $level, None, client_name)
+            }
+
+            pub fn $named_error(
+                message: Object,
+                exception: ExternalError,
+                client_name: String,
+            ) -> Result<(), Error> {
+                Self::log_named(message, $level, Some(exception), client_name)
+            }
+        }
+    };
+}
+
+level_methods!(
+    trace_with_object_grid_client,
+    trace_with_object_exception_grid_client,
+    trace_with_object_string,
+    trace_with_object_exception_string,
+    LogLevel::TRACE
+);
+level_methods!(
+    debug_with_object_grid_client,
+    debug_with_object_exception_grid_client,
+    debug_with_object_string,
+    debug_with_object_exception_string,
+    LogLevel::DEBUG
+);
+level_methods!(
+    info_with_object_grid_client,
+    info_with_object_exception_grid_client,
+    info_with_object_string,
+    info_with_object_exception_string,
+    LogLevel::INFORMATION
+);
+level_methods!(
+    warn_with_object_grid_client,
+    warn_with_object_exception_grid_client,
+    warn_with_object_string,
+    warn_with_object_exception_string,
+    LogLevel::WARNING
+);
+level_methods!(
+    error_with_object_grid_client,
+    error_with_object_exception_grid_client,
+    error_with_object_string,
+    error_with_object_exception_string,
+    LogLevel::ERROR
+);
+level_methods!(
+    critical_with_object_grid_client,
+    critical_with_object_exception_grid_client,
+    critical_with_object_string,
+    critical_with_object_exception_string,
+    LogLevel::CRITICAL
+);
+
+#[cfg(test)]
+mod tests {
+    use super::*;
+    use std::sync::atomic::AtomicUsize;
+
+    #[test]
+    fn event_subscription_delivers_and_unregisters() {
+        Logger::shutdown_with_method().unwrap();
+        let calls = Arc::new(AtomicUsize::new(0));
+        let observed = Arc::clone(&calls);
+        let subscription = Logger::subscribe_on_log_message(Some(
+            LoggerLogCallback::from_callback(move |_, _| {
+                observed.fetch_add(1, Ordering::Relaxed);
+            }),
+        ));
+        Logger::info_with_object_grid_client(Object::String("one".to_owned()), None).unwrap();
+        for _ in 0..100 {
+            if calls.load(Ordering::Relaxed) == 1 {
+                break;
+            }
+            std::thread::sleep(Duration::from_millis(1));
+        }
+        assert_eq!(calls.load(Ordering::Relaxed), 1);
+        drop(subscription);
+        Logger::info_with_object_grid_client(Object::String("two".to_owned()), None).unwrap();
+        std::thread::sleep(Duration::from_millis(10));
+        assert_eq!(calls.load(Ordering::Relaxed), 1);
+        Logger::shutdown_with_method().unwrap();
+    }
+
+    #[test]
+    fn scope_close_is_idempotent() {
+        let _ = ensure_initialized();
+        let mut scope = Logger::begin_scope(Object::String("test".to_owned())).unwrap();
+        scope.close().unwrap();
+        scope.close().unwrap();
+        Logger::shutdown_with_method().unwrap();
+    }
+}