MetaCrate/crates/libremetaverse/src/logger.rs

//! 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();
    }
}