aviutl2 0.17.0

//! AviUtl2のロガーへのインターフェースを提供します。

use crate::common::{CWString, NullByteError};
pub use log::LevelFilter;

// NOTE:
// InitializeLoggerは可能な限り早く実行されるらしいので、まぁ捨てられるログはないとしていいはず...

/// フォーマッター。
///
/// # See Also
///
/// [`LogBuilder::formatter`]
pub type Formatter = dyn Fn(&log::Record) -> String + Send + Sync + 'static;

/// [`log`]クレートを使用してAviUtl2のログ出力を設定するためのビルダー。
///
/// # Note
///
/// Debug、TraceレベルのログはVERBOSEとしてまとめられます。
///
/// # See Also
///
/// - [`env_filter::Builder`](https://docs.rs/env_filter/latest/env_filter/struct.Builder.html)
#[must_use]
pub struct LogBuilder {
    filter: env_filter::Builder,
    formatter: Option<Box<Formatter>>,
}

impl LogBuilder {
    /// 新しい`LogBuilder`を作成します。
    pub fn new() -> Self {
        LogBuilder {
            filter: env_filter::Builder::new(),
            formatter: None,
        }
    }

    /// 全てのモジュールのログレベルを設定します。
    pub fn filter_level(mut self, level: log::LevelFilter) -> Self {
        self.filter.filter_level(level);
        self
    }

    /// 指定したモジュールのログレベルを設定します。
    pub fn filter_module(mut self, module: &str, level: log::LevelFilter) -> Self {
        self.filter.filter_module(module, level);
        self
    }

    /// ログのフォーマッタを設定します。
    pub fn formatter<F>(mut self, formatter: F) -> Self
    where
        F: Fn(&log::Record) -> String + Send + Sync + 'static,
    {
        self.formatter = Some(Box::new(formatter));
        self
    }

    /// ログのフォーマッターをデフォルトのものに設定します。
    pub fn default_formatter(mut self) -> Self {
        self.formatter = None;
        self
    }

    /// ロガーを初期化します。
    ///
    /// [`LogBuilder::try_init`]と異なり、エラーが発生した場合にパニックします。
    pub fn init(self) {
        self.try_init().expect("Failed to initialize logger")
    }

    /// ロガーを初期化します。
    ///
    /// # Errors
    ///
    /// ロガーを2回以上初期化しようとした場合にエラーを返します。
    pub fn try_init(self) -> Result<(), log::SetLoggerError> {
        let LogBuilder {
            mut filter,
            formatter,
        } = self;
        let filter = filter.build();
        let logger = InternalLogger::new(formatter.unwrap_or_else(|| {
            Box::new(|record: &log::Record| format!("[{}] {}", record.target(), record.args()))
        }));
        log::set_max_level(filter.filter());
        let logger = env_filter::FilteredLog::new(logger, filter);
        log::set_boxed_logger(Box::new(logger))?;
        Ok(())
    }
}

impl Default for LogBuilder {
    fn default() -> Self {
        Self::new()
    }
}
struct InternalLogger {
    formatter: Box<Formatter>,
}

impl InternalLogger {
    fn new(formatter: Box<Formatter>) -> Self {
        InternalLogger { formatter }
    }
}

// NOTE: env_filterがいい感じにやってくれるらしい（ありがたい）
impl log::Log for InternalLogger {
    fn enabled(&self, _metadata: &log::Metadata) -> bool {
        true
    }

    fn log(&self, record: &log::Record) {
        let message = (self.formatter)(record);
        send_record(record.level(), message);
    }

    fn flush(&self) {
        // No-op
    }
}

/// プラグイン用ログに出力する[`dbg!`]マクロ。
///
/// # See Also
/// <https://github.com/rust-lang/rust/blob/29483883eed69d5fb4db01964cdf2af4d86e9cb2/library/std/src/macros.rs#L352>
#[macro_export]
macro_rules! ldbg {
    () => {
        $crate::lprintln!(verbose, "[{}:{}:{}]", ::std::file!(), ::std::line!(), ::std::column!());
    };
    ($val:expr $(,)?) => {
        match $val {
            tmp => {
                $crate::lprintln!(verbose, "[{}:{}:{}] {} = {:#?}",
                    ::std::file!(),
                    ::std::line!(),
                    ::std::column!(),
                    ::std::stringify!($val),
                    &&tmp as &dyn ::std::fmt::Debug,
                );
                tmp
            }
        }
    };
    ($($val:expr),+ $(,)?) => {
        ($($crate::ldbg!($val)),+,)
    };
}

/// プラグイン用ログに出力する[`println!`]マクロ。
///
/// ```rust
/// # use aviutl2::lprintln;
/// lprintln!("This is a plugin log message.");  // デフォルトはpluginログに出力
/// lprintln!(plugin, "This is also a plugin log message.");
/// lprintln!(info, "This is an info log message.");
/// lprintln!(warn, "This is a warning log message.");
/// lprintln!(error, "This is an error log message.");
/// lprintln!(verbose, "This is a verbose log message.");
/// ```
#[macro_export]
macro_rules! lprintln {
    (plugin, $($arg:tt)*) => {
        ::std::mem::drop($crate::logger::write_plugin_log(&format!($($arg)*)));
    };
    (info, $($arg:tt)*) => {
        ::std::mem::drop($crate::logger::write_info_log(&format!($($arg)*)));
    };
    (warn, $($arg:tt)*) => {
        ::std::mem::drop($crate::logger::write_warn_log(&format!($($arg)*)));
    };
    (error, $($arg:tt)*) => {
        ::std::mem::drop($crate::logger::write_error_log(&format!($($arg)*)));
    };
    (verbose, $($arg:tt)*) => {
        ::std::mem::drop($crate::logger::write_verbose_log(&format!($($arg)*)));
    };
    ($($arg:tt)*) => {
        $crate::lprintln!(plugin, $($arg)*);
    };
}

#[cfg(feature = "wrap_log")]
fn log_length_limit(kind_length: usize) -> usize {
    static DLL_LENGTH: std::sync::OnceLock<usize> = std::sync::OnceLock::new();
    let dll_length = *DLL_LENGTH.get_or_init(|| {
        process_path::get_dylib_path()
            .map_or(0, |path| path.file_name().unwrap().to_string_lossy().len())
    });
    // [01/23 08:43:47] [VERBOSE] [Plugin::vi5.aux2] ...
    1023 - 35 - dll_length - kind_length
}
#[cfg(not(feature = "wrap_log"))]
fn log_length_limit(_kind_length: usize) -> usize {
    // wrap_logが無効な場合は制限なし
    usize::MAX
}

fn split_into_chunks(message: &str, kind_length: usize) -> Vec<String> {
    // 二分探索みたいなことをすればもっと効率的にできるけど面倒なので...
    let log_length_limit = log_length_limit(kind_length);
    let mut chunks = Vec::with_capacity(message.len() / log_length_limit + 1);
    let mut current_chunk = String::new();
    for letter in message.chars() {
        let letter_len = letter.len_utf8();
        if current_chunk.len() + letter_len > log_length_limit {
            chunks.push(std::mem::take(&mut current_chunk));
        }
        current_chunk.push(letter);
    }
    if !current_chunk.is_empty() {
        chunks.push(current_chunk);
    }
    chunks
}

/// プラグイン用ログにメッセージを書き込みます。
///
/// # Note
///
/// ロガーが初期化されていない場合は何も行いません。
///
/// # See Also
///
/// - [`ldbg!`]
/// - [`lprintln!`]
pub fn write_plugin_log(message: &str) -> Result<(), NullByteError> {
    with_logger_handle(|handle| unsafe {
        for chunk in split_into_chunks(message, "PLUGIN".len()) {
            let wide_message = CWString::new(&chunk)?;
            ((*handle).log)(handle, wide_message.as_ptr());
        }
        Ok(())
    })
    .unwrap_or(Ok(()))
}

#[duplicate::duplicate_item(
    level       function_name       log_method;
    ["ERROR"]   [write_error_log]   [error];
    ["WARN"]    [write_warn_log]    [warn];
    ["INFO"]    [write_info_log]    [info];
    ["VERBOSE"] [write_verbose_log] [verbose];
)]
#[doc = concat!("ログに", level, "レベルのメッセージを書き込みます。")]
///
/// # Note
///
/// ロガーが初期化されていない場合は何も行いません。
///
/// # See Also
///
/// - [`ldbg!`]
/// - [`lprintln!`]
pub fn function_name(message: &str) -> Result<(), NullByteError> {
    with_logger_handle(|handle| unsafe {
        for chunk in split_into_chunks(message, level.len()) {
            let wide_message = CWString::new(&chunk)?;
            ((*handle).log_method)(handle, wide_message.as_ptr());
        }
        Ok(())
    })
    .unwrap_or(Ok(()))
}

struct InternalLoggerHandle(*mut aviutl2_sys::logger2::LOG_HANDLE);
unsafe impl Send for InternalLoggerHandle {}

static LOGGER_HANDLE: std::sync::OnceLock<std::sync::Mutex<InternalLoggerHandle>> =
    std::sync::OnceLock::new();

#[doc(hidden)]
pub fn __initialize_logger(handle: *mut aviutl2_sys::logger2::LOG_HANDLE) {
    let internal_handle = InternalLoggerHandle(handle);
    LOGGER_HANDLE
        .set(std::sync::Mutex::new(internal_handle))
        .unwrap_or_else(|_| {
            panic!("Logger has already been initialized");
        });
}

#[doc(hidden)]
pub fn __initialize_logger_unwind(handle: *mut aviutl2_sys::logger2::LOG_HANDLE) {
    if let Err(panic_info) =
        crate::utils::catch_unwind_with_panic_info(|| __initialize_logger(handle))
    {
        crate::log::error!("Panic occurred during InitializeLogger: {}", panic_info);
        let _ = crate::logger::write_error_log(&panic_info);
    }
}

impl InternalLoggerHandle {
    fn ptr(&self) -> *mut aviutl2_sys::logger2::LOG_HANDLE {
        self.0
    }
}

fn with_logger_handle<F, T>(f: F) -> Option<T>
where
    F: FnOnce(*mut aviutl2_sys::logger2::LOG_HANDLE) -> T,
{
    let handle = LOGGER_HANDLE.get()?;
    let handle = handle.lock().unwrap();
    let handle_ptr = handle.ptr();
    Some(f(handle_ptr))
}

fn send_record(level: log::Level, message: String) {
    match level {
        log::Level::Error => {
            let _ = write_error_log(&message);
        }
        log::Level::Warn => {
            let _ = write_warn_log(&message);
        }
        log::Level::Info => {
            let _ = write_info_log(&message);
        }
        log::Level::Debug | log::Level::Trace => {
            let _ = write_verbose_log(&message);
        }
    }
}

#[cfg(test)]
mod tests {
    #[test]
    fn test_can_compile_ldbg() {
        let x = 42;
        ldbg!();
        ldbg!(x);
        ldbg!(x + 1, x * 2);
    }

    #[test]
    fn test_can_compile_lprintln() {
        lprintln!("This is a test log message.");
        lprintln!(info, "This is an info log message.");
        lprintln!(warn, "This is a warning log message.");
        lprintln!(error, "This is an error log message.");
        lprintln!(verbose, "This is a verbose log message.");
    }

    #[test]
    #[cfg(feature = "wrap_log")]
    fn test_split_into_chunks() {
        let message = "a".repeat(5000);
        let chunks = super::split_into_chunks(&message, "VERBOSE".len());
        let dylib_name = process_path::get_dylib_path()
            .and_then(|path| {
                path.file_name()
                    .map(|name| name.to_string_lossy().into_owned())
            })
            .unwrap();
        for chunk in chunks {
            assert!(chunk.len() <= super::log_length_limit("VERBOSE".len()));
            assert!(
                format!(
                    "[01/23 08:43:47] [VERBOSE] [Plugin::{}] {}",
                    dylib_name, chunk
                )
                .len()
                    <= 1023
            );
        }
    }
}