aviutl2/
logger.rs

1//! AviUtl2のロガーへのインターフェースを提供します。
2//!
3//! # Examples
4//!
5//! AviUtl2のロガーに直接書き込むことができます。
6//!
7//! ```rust
8//! aviutl2::logger::write_plugin_log("This is a plugin log message.").unwrap();
9//! aviutl2::logger::write_info_log("This is an info log message.").unwrap();
10//! aviutl2::logger::write_warn_log("This is a warning log message.").unwrap();
11//! aviutl2::logger::write_error_log("This is an error log message.").unwrap();
12//! aviutl2::logger::write_verbose_log("This is a verbose log message.").unwrap();
13//!
14//! aviutl2::lprintln!("This is a plugin log message.");  // デフォルトはpluginログに出力
15//! aviutl2::lprintln!(plugin, "This is also a plugin log message.");
16//! aviutl2::lprintln!(info, "This is an info log message.");
17//! aviutl2::lprintln!(warn, "This is a warning log message.");
18//! aviutl2::lprintln!(error, "This is an error log message.");
19//! aviutl2::lprintln!(verbose, "This is a verbose log message.");
20//!
21//! aviutl2::ldbg!(42); // dbg!マクロに相当
22//! ```
23//!
24//! [`tracing`]クレートと組み合わせることもできます。
25//!
26//! ```rust
27//! aviutl2::tracing_subscriber::fmt()
28//!     .with_max_level(if cfg!(debug_assertions) {
29//!         tracing::Level::DEBUG
30//!     } else {
31//!         tracing::Level::INFO
32//!     })
33//!     .event_format(aviutl2::logger::AviUtl2Formatter)
34//!     .with_writer(aviutl2::logger::AviUtl2LogWriter)
35//!     .init();
36//!
37//! tracing::info!("This is an info log message using tracing.");
38//! ```
39
40use crate::common::{CWString, NullByteError};
41use tracing_log::NormalizeEvent;
42use tracing_subscriber::fmt::FormatFields;
43
44// NOTE:
45// InitializeLoggerは可能な限り早く実行されるらしいので、まぁ捨てられるログはないとしていいはず...
46
47/// [`tracing_subscriber::fmt::FormatEvent`]を実装する構造体。
48///
49/// AviUtl2風のログフォーマットでイベントをフォーマットします。
50#[derive(Debug, Clone, Default)]
51pub struct AviUtl2Formatter;
52
53impl<C, N> tracing_subscriber::fmt::FormatEvent<C, N> for AviUtl2Formatter
54where
55    C: tracing::Subscriber + for<'a> tracing_subscriber::registry::LookupSpan<'a>,
56    N: for<'a> tracing_subscriber::fmt::FormatFields<'a> + 'static,
57{
58    fn format_event(
59        &self,
60        ctx: &tracing_subscriber::fmt::FmtContext<'_, C, N>,
61        mut writer: tracing_subscriber::fmt::format::Writer<'_>,
62        event: &tracing::Event<'_>,
63    ) -> std::fmt::Result {
64        let mut writer = tracing_subscriber::fmt::format::Writer::new(&mut writer);
65        let meta = event.normalized_metadata();
66        let meta = meta.as_ref().unwrap_or_else(|| event.metadata());
67        let target = meta.target();
68        write!(writer, "[{target}] ")?;
69        ctx.format_fields(writer.by_ref(), event)?;
70        writer.write_str("\n")?;
71        Ok(())
72    }
73}
74
75/// [`tracing_subscriber::fmt::MakeWriter`]を実装する構造体。
76///
77/// AviUtl2のログに書き込みます。
78#[derive(Debug, Clone, Default)]
79pub struct AviUtl2LogWriter;
80
81impl tracing_subscriber::fmt::MakeWriter<'_> for AviUtl2LogWriter {
82    type Writer = LockedInternalWriter;
83
84    fn make_writer(&self) -> Self::Writer {
85        LockedInternalWriter::plugin()
86    }
87
88    fn make_writer_for(&'_ self, meta: &tracing::Metadata<'_>) -> Self::Writer {
89        match *meta.level() {
90            tracing::Level::ERROR => LockedInternalWriter::error(),
91            tracing::Level::WARN => LockedInternalWriter::warn(),
92            tracing::Level::INFO => LockedInternalWriter::info(),
93            tracing::Level::DEBUG | tracing::Level::TRACE => LockedInternalWriter::verbose(),
94        }
95    }
96}
97
98static INTERNAL_WRITER_MUTEX_PLUGIN: std::sync::LazyLock<std::sync::Mutex<InternalWriter>> =
99    std::sync::LazyLock::new(|| {
100        std::sync::Mutex::new(InternalWriter::new(InternalWriterLevel::Plugin))
101    });
102static INTERNAL_WRITER_MUTEX_INFO: std::sync::LazyLock<std::sync::Mutex<InternalWriter>> =
103    std::sync::LazyLock::new(|| {
104        std::sync::Mutex::new(InternalWriter::new(InternalWriterLevel::Info))
105    });
106static INTERNAL_WRITER_MUTEX_WARN: std::sync::LazyLock<std::sync::Mutex<InternalWriter>> =
107    std::sync::LazyLock::new(|| {
108        std::sync::Mutex::new(InternalWriter::new(InternalWriterLevel::Warn))
109    });
110static INTERNAL_WRITER_MUTEX_ERROR: std::sync::LazyLock<std::sync::Mutex<InternalWriter>> =
111    std::sync::LazyLock::new(|| {
112        std::sync::Mutex::new(InternalWriter::new(InternalWriterLevel::Error))
113    });
114static INTERNAL_WRITER_MUTEX_VERBOSE: std::sync::LazyLock<std::sync::Mutex<InternalWriter>> =
115    std::sync::LazyLock::new(|| {
116        std::sync::Mutex::new(InternalWriter::new(InternalWriterLevel::Verbose))
117    });
118
119pub struct LockedInternalWriter {
120    mutex: &'static std::sync::Mutex<InternalWriter>,
121}
122
123impl LockedInternalWriter {
124    pub fn plugin() -> Self {
125        Self {
126            mutex: &INTERNAL_WRITER_MUTEX_PLUGIN,
127        }
128    }
129
130    pub fn info() -> Self {
131        Self {
132            mutex: &INTERNAL_WRITER_MUTEX_INFO,
133        }
134    }
135
136    pub fn warn() -> Self {
137        Self {
138            mutex: &INTERNAL_WRITER_MUTEX_WARN,
139        }
140    }
141
142    pub fn error() -> Self {
143        Self {
144            mutex: &INTERNAL_WRITER_MUTEX_ERROR,
145        }
146    }
147
148    pub fn verbose() -> Self {
149        Self {
150            mutex: &INTERNAL_WRITER_MUTEX_VERBOSE,
151        }
152    }
153}
154impl std::io::Write for LockedInternalWriter {
155    fn write(&mut self, buf: &[u8]) -> std::io::Result<usize> {
156        let mut writer = self.mutex.lock().unwrap();
157        writer.write(buf)
158    }
159
160    fn flush(&mut self) -> std::io::Result<()> {
161        let mut writer = self.mutex.lock().unwrap();
162        writer.flush()
163    }
164}
165
166enum InternalWriterLevel {
167    Plugin,
168    Info,
169    Warn,
170    Error,
171    Verbose,
172}
173
174struct InternalWriter {
175    level: InternalWriterLevel,
176    buffer: Vec<u8>,
177}
178impl InternalWriter {
179    fn new(level: InternalWriterLevel) -> Self {
180        Self {
181            level,
182            buffer: Vec::new(),
183        }
184    }
185}
186
187impl std::io::Write for InternalWriter {
188    fn write(&mut self, buf: &[u8]) -> std::io::Result<usize> {
189        self.buffer.extend_from_slice(buf);
190        self.flush()?;
191        Ok(buf.len())
192    }
193
194    fn flush(&mut self) -> std::io::Result<()> {
195        while let Some(pos) = self.buffer.iter().position(|&b| b == b'\n') {
196            let line = self.buffer.drain(..=pos).collect::<Vec<u8>>();
197            let line = String::from_utf8_lossy(&line);
198            let line = line.trim_end_matches('\n');
199            match self.level {
200                InternalWriterLevel::Plugin => {
201                    let _ = write_plugin_log(line);
202                }
203                InternalWriterLevel::Info => {
204                    let _ = write_info_log(line);
205                }
206                InternalWriterLevel::Warn => {
207                    let _ = write_warn_log(line);
208                }
209                InternalWriterLevel::Error => {
210                    let _ = write_error_log(line);
211                }
212                InternalWriterLevel::Verbose => {
213                    let _ = write_verbose_log(line);
214                }
215            }
216        }
217        Ok(())
218    }
219}
220
221/// プラグイン用ログに出力する[`dbg!`]マクロ。
222///
223/// # See Also
224/// <https://github.com/rust-lang/rust/blob/29483883eed69d5fb4db01964cdf2af4d86e9cb2/library/std/src/macros.rs#L352>
225#[macro_export]
226macro_rules! ldbg {
227    () => {
228        $crate::lprintln!(verbose, "[{}:{}:{}]", ::std::file!(), ::std::line!(), ::std::column!());
229    };
230    ($val:expr $(,)?) => {
231        match $val {
232            tmp => {
233                $crate::lprintln!(verbose, "[{}:{}:{}] {} = {:#?}",
234                    ::std::file!(),
235                    ::std::line!(),
236                    ::std::column!(),
237                    ::std::stringify!($val),
238                    &&tmp as &dyn ::std::fmt::Debug,
239                );
240                tmp
241            }
242        }
243    };
244    ($($val:expr),+ $(,)?) => {
245        ($($crate::ldbg!($val)),+,)
246    };
247}
248
249/// プラグイン用ログに出力する[`println!`]マクロ。
250///
251/// ```rust
252/// # use aviutl2::lprintln;
253/// lprintln!("This is a plugin log message.");  // デフォルトはpluginログに出力
254/// lprintln!(plugin, "This is also a plugin log message.");
255/// lprintln!(info, "This is an info log message.");
256/// lprintln!(warn, "This is a warning log message.");
257/// lprintln!(error, "This is an error log message.");
258/// lprintln!(verbose, "This is a verbose log message.");
259/// ```
260#[macro_export]
261macro_rules! lprintln {
262    (plugin, $($arg:tt)*) => {
263        ::std::mem::drop($crate::logger::write_plugin_log(&format!($($arg)*)));
264    };
265    (info, $($arg:tt)*) => {
266        ::std::mem::drop($crate::logger::write_info_log(&format!($($arg)*)));
267    };
268    (warn, $($arg:tt)*) => {
269        ::std::mem::drop($crate::logger::write_warn_log(&format!($($arg)*)));
270    };
271    (error, $($arg:tt)*) => {
272        ::std::mem::drop($crate::logger::write_error_log(&format!($($arg)*)));
273    };
274    (verbose, $($arg:tt)*) => {
275        ::std::mem::drop($crate::logger::write_verbose_log(&format!($($arg)*)));
276    };
277    ($($arg:tt)*) => {
278        $crate::lprintln!(plugin, $($arg)*);
279    };
280}
281
282#[cfg(feature = "wrap_log")]
283fn log_length_limit(kind_length: usize) -> usize {
284    static DLL_LENGTH: std::sync::OnceLock<usize> = std::sync::OnceLock::new();
285    let dll_length = *DLL_LENGTH.get_or_init(|| {
286        process_path::get_dylib_path()
287            .map_or(0, |path| path.file_name().unwrap().to_string_lossy().len())
288    });
289    // [01/23 08:43:47] [VERBOSE] [Plugin::vi5.aux2] ...
290    1023 - 35 - dll_length - kind_length
291}
292#[cfg(not(feature = "wrap_log"))]
293fn log_length_limit(_kind_length: usize) -> usize {
294    // wrap_logが無効な場合は制限なし
295    usize::MAX
296}
297
298fn split_into_chunks(message: &str, kind_length: usize) -> Vec<String> {
299    // 二分探索みたいなことをすればもっと効率的にできるけど面倒なので...
300    let log_length_limit = log_length_limit(kind_length);
301    let mut chunks = Vec::with_capacity(message.len() / log_length_limit + 1);
302    let mut current_chunk = String::new();
303    for letter in message.chars() {
304        let letter_len = letter.len_utf8();
305        if current_chunk.len() + letter_len > log_length_limit {
306            chunks.push(std::mem::take(&mut current_chunk));
307        }
308        current_chunk.push(letter);
309    }
310    if !current_chunk.is_empty() {
311        chunks.push(current_chunk);
312    }
313    chunks
314}
315
316/// プラグイン用ログにメッセージを書き込みます。
317///
318/// # Note
319///
320/// ロガーが初期化されていない場合は何も行いません。
321///
322/// # See Also
323///
324/// - [`ldbg!`]
325/// - [`lprintln!`]
326pub fn write_plugin_log(message: &str) -> Result<(), NullByteError> {
327    with_logger_handle(|handle| unsafe {
328        for chunk in split_into_chunks(message, "PLUGIN".len()) {
329            let wide_message = CWString::new(&chunk)?;
330            ((*handle).log)(handle, wide_message.as_ptr());
331        }
332        Ok(())
333    })
334    .unwrap_or(Ok(()))
335}
336
337#[duplicate::duplicate_item(
338    level       function_name       log_method;
339    ["ERROR"]   [write_error_log]   [error];
340    ["WARN"]    [write_warn_log]    [warn];
341    ["INFO"]    [write_info_log]    [info];
342    ["VERBOSE"] [write_verbose_log] [verbose];
343)]
344#[doc = concat!("ログに", level, "レベルのメッセージを書き込みます。")]
345///
346/// # Note
347///
348/// ロガーが初期化されていない場合は何も行いません。
349///
350/// # See Also
351///
352/// - [`ldbg!`]
353/// - [`lprintln!`]
354pub fn function_name(message: &str) -> Result<(), NullByteError> {
355    with_logger_handle(|handle| unsafe {
356        for chunk in split_into_chunks(message, level.len()) {
357            let wide_message = CWString::new(&chunk)?;
358            ((*handle).log_method)(handle, wide_message.as_ptr());
359        }
360        Ok(())
361    })
362    .unwrap_or(Ok(()))
363}
364
365struct InternalLoggerHandle(*mut aviutl2_sys::logger2::LOG_HANDLE);
366unsafe impl Send for InternalLoggerHandle {}
367
368static LOGGER_HANDLE: std::sync::OnceLock<std::sync::Mutex<InternalLoggerHandle>> =
369    std::sync::OnceLock::new();
370
371#[doc(hidden)]
372pub fn __initialize_logger(handle: *mut aviutl2_sys::logger2::LOG_HANDLE) {
373    let internal_handle = InternalLoggerHandle(handle);
374    LOGGER_HANDLE
375        .set(std::sync::Mutex::new(internal_handle))
376        .unwrap_or_else(|_| {
377            panic!("Logger has already been initialized");
378        });
379}
380
381#[doc(hidden)]
382pub fn __initialize_logger_unwind(handle: *mut aviutl2_sys::logger2::LOG_HANDLE) {
383    if let Err(panic_info) =
384        crate::utils::catch_unwind_with_panic_info(|| __initialize_logger(handle))
385    {
386        crate::tracing::error!("Panic occurred during InitializeLogger: {}", panic_info);
387        let _ = crate::logger::write_error_log(&panic_info);
388    }
389}
390
391impl InternalLoggerHandle {
392    fn ptr(&self) -> *mut aviutl2_sys::logger2::LOG_HANDLE {
393        self.0
394    }
395}
396
397fn with_logger_handle<F, T>(f: F) -> Option<T>
398where
399    F: FnOnce(*mut aviutl2_sys::logger2::LOG_HANDLE) -> T,
400{
401    let handle = LOGGER_HANDLE.get()?;
402    let handle = handle.lock().unwrap();
403    let handle_ptr = handle.ptr();
404    Some(f(handle_ptr))
405}
406
407#[cfg(test)]
408mod tests {
409    #[test]
410    fn aviutl2_formatter_does_not_emit_ansi_escape_codes() {
411        struct TestWriter(std::sync::Arc<std::sync::Mutex<Vec<u8>>>);
412
413        impl std::io::Write for TestWriter {
414            fn write(&mut self, buf: &[u8]) -> std::io::Result<usize> {
415                std::io::Write::write(&mut *self.0.lock().unwrap(), buf)
416            }
417
418            fn flush(&mut self) -> std::io::Result<()> {
419                std::io::Write::flush(&mut *self.0.lock().unwrap())
420            }
421        }
422
423        let output = std::sync::Arc::new(std::sync::Mutex::new(Vec::new()));
424        let test_output = output.clone();
425        let subscriber = tracing_subscriber::fmt()
426            .with_ansi(true)
427            .event_format(super::AviUtl2Formatter)
428            .with_writer(move || TestWriter(test_output.clone()))
429            .finish();
430
431        tracing::subscriber::with_default(subscriber, || {
432            tracing::info!(answer = 42, "test message");
433        });
434
435        let output = output.lock().unwrap();
436        assert!(!output.contains(&b'\x1b'));
437        let output = std::str::from_utf8(&output).unwrap();
438        assert!(output.contains("test message"));
439        assert!(output.contains("answer=42"));
440    }
441
442    #[test]
443    fn test_can_compile_ldbg() {
444        let x = 42;
445        ldbg!();
446        ldbg!(x);
447        ldbg!(x + 1, x * 2);
448    }
449
450    #[test]
451    fn test_can_compile_lprintln() {
452        lprintln!("This is a test log message.");
453        lprintln!(info, "This is an info log message.");
454        lprintln!(warn, "This is a warning log message.");
455        lprintln!(error, "This is an error log message.");
456        lprintln!(verbose, "This is a verbose log message.");
457    }
458
459    #[test]
460    #[cfg(feature = "wrap_log")]
461    fn test_split_into_chunks() {
462        let message = "a".repeat(5000);
463        let chunks = super::split_into_chunks(&message, "VERBOSE".len());
464        let dylib_name = process_path::get_dylib_path()
465            .and_then(|path| {
466                path.file_name()
467                    .map(|name| name.to_string_lossy().into_owned())
468            })
469            .unwrap();
470        for chunk in chunks {
471            assert!(chunk.len() <= super::log_length_limit("VERBOSE".len()));
472            assert!(
473                format!(
474                    "[01/23 08:43:47] [VERBOSE] [Plugin::{}] {}",
475                    dylib_name, chunk
476                )
477                .len()
478                    <= 1023
479            );
480        }
481    }
482}
aviutl2/logger.rs

aviutl2/
logger.rs
