Merge pull request #200 from tazz4843/update-logging

Make logging generic across backends and simplify logging code

.github/workflows/pr.yml

@@ -73,4 +73,4 @@ jobs:
           toolchain: ${{ matrix.rust-version }}
 
       - name: Check build
-        run: cargo build -F whisper-cpp-log,whisper-cpp-tracing --verbose --examples
+        run: cargo build -F log_backend,tracing_backend --verbose --examples

Cargo.toml

@@ -32,8 +32,14 @@ hipblas = ["whisper-rs-sys/hipblas", "_gpu"]
 openblas = ["whisper-rs-sys/openblas"]
 metal = ["whisper-rs-sys/metal", "_gpu"]
 vulkan = ["whisper-rs-sys/vulkan", "_gpu"]
+openmp = ["whisper-rs-sys/openmp"]
 _gpu = []
 test-with-tiny-model = []
-whisper-cpp-log = ["dep:log"]
-whisper-cpp-tracing = ["dep:tracing"]
-openmp = ["whisper-rs-sys/openmp"]
+
+# Bring logs into Rust via the log crate. *Warning*: not mutually exclusive with tracing_backend,
+# will result in duplicate logs if both are enabled and one consumes logs from the other.
+log_backend = ["dep:log"]
+
+# Bring logs into Rust via the tracing crate. *Warning*: not mutually exclusive with log_backend,
+# will result in duplicate logs if both are enabled and one consumes logs from the other.
+tracing_backend = ["dep:tracing"]

src/common_logging.rs

@@ -0,0 +1,76 @@
+macro_rules! generic_error {
+    ($($expr:tt)*) => {
+        #[cfg(feature = "log_backend")]
+        log::error!($($expr)*);
+        #[cfg(feature = "tracing_backend")]
+        tracing::error!($($expr)*);
+    };
+}
+
+macro_rules! generic_warn {
+    ($($expr:tt)*) => {
+        #[cfg(feature = "log_backend")]
+        log::warn!($($expr)*);
+        #[cfg(feature = "tracing_backend")]
+        tracing::warn!($($expr)*);
+    }
+}
+
+macro_rules! generic_info {
+    ($($expr:tt)*) => {
+        #[cfg(feature = "log_backend")]
+        log::info!($($expr)*);
+        #[cfg(feature = "tracing_backend")]
+        tracing::info!($($expr)*);
+    }
+}
+
+macro_rules! generic_debug {
+    ($($expr:tt)*) => {
+        #[cfg(feature = "log_backend")]
+        log::debug!($($expr)*);
+        #[cfg(feature = "tracing_backend")]
+        tracing::debug!($($expr)*);
+    }
+}
+
+macro_rules! generic_trace {
+    ($($expr:tt)*) => {
+        #[cfg(feature = "log_backend")]
+        log::trace!($($expr)*);
+        #[cfg(feature = "tracing_backend")]
+        tracing::trace!($($expr)*);
+    }
+}
+
+use whisper_rs_sys::ggml_log_level;
+pub(crate) use {generic_debug, generic_error, generic_info, generic_trace, generic_warn};
+
+// Unsigned integer type on most platforms is 32 bit, niche platforms that whisper.cpp
+// likely doesn't even support would use 16 bit and would still fit
+#[cfg_attr(any(not(windows), target_env = "gnu"), repr(u32))]
+// Of course Windows thinks it's a special little shit and
+// picks a signed integer for an unsigned type
+#[cfg_attr(all(windows, not(target_env = "gnu")), repr(i32))]
+pub(crate) enum GGMLLogLevel {
+    None = whisper_rs_sys::ggml_log_level_GGML_LOG_LEVEL_NONE,
+    Info = whisper_rs_sys::ggml_log_level_GGML_LOG_LEVEL_INFO,
+    Warn = whisper_rs_sys::ggml_log_level_GGML_LOG_LEVEL_WARN,
+    Error = whisper_rs_sys::ggml_log_level_GGML_LOG_LEVEL_ERROR,
+    Debug = whisper_rs_sys::ggml_log_level_GGML_LOG_LEVEL_DEBUG,
+    Cont = whisper_rs_sys::ggml_log_level_GGML_LOG_LEVEL_CONT,
+    Unknown(ggml_log_level),
+}
+impl From<ggml_log_level> for GGMLLogLevel {
+    fn from(level: ggml_log_level) -> Self {
+        match level {
+            whisper_rs_sys::ggml_log_level_GGML_LOG_LEVEL_NONE => GGMLLogLevel::None,
+            whisper_rs_sys::ggml_log_level_GGML_LOG_LEVEL_INFO => GGMLLogLevel::Info,
+            whisper_rs_sys::ggml_log_level_GGML_LOG_LEVEL_WARN => GGMLLogLevel::Warn,
+            whisper_rs_sys::ggml_log_level_GGML_LOG_LEVEL_ERROR => GGMLLogLevel::Error,
+            whisper_rs_sys::ggml_log_level_GGML_LOG_LEVEL_DEBUG => GGMLLogLevel::Debug,
+            whisper_rs_sys::ggml_log_level_GGML_LOG_LEVEL_CONT => GGMLLogLevel::Cont,
+            other => GGMLLogLevel::Unknown(other),
+        }
+    }
+}

src/ggml_logging_hook.rs

@@ -0,0 +1,73 @@
+use crate::common_logging::{
+    generic_debug, generic_error, generic_info, generic_trace, generic_warn, GGMLLogLevel,
+};
+use core::ffi::{c_char, c_void};
+use std::borrow::Cow;
+use std::ffi::CStr;
+use std::sync::Once;
+use whisper_rs_sys::ggml_log_level;
+
+static GGML_LOG_TRAMPOLINE_INSTALL: Once = Once::new();
+pub(crate) fn install_ggml_logging_hook() {
+    GGML_LOG_TRAMPOLINE_INSTALL.call_once(|| unsafe {
+        whisper_rs_sys::ggml_log_set(Some(ggml_logging_trampoline), std::ptr::null_mut())
+    });
+}
+
+unsafe extern "C" fn ggml_logging_trampoline(
+    level: ggml_log_level,
+    text: *const c_char,
+    _: *mut c_void, // user_data
+) {
+    if text.is_null() {
+        generic_error!("ggml_logging_trampoline: text is nullptr");
+    }
+    let level = GGMLLogLevel::from(level);
+
+    // SAFETY: we must trust ggml that it will not pass us a string that does not satisfy
+    // from_ptr's requirements.
+    let log_str = unsafe { CStr::from_ptr(text) }.to_string_lossy();
+
+    ggml_logging_trampoline_safe(level, log_str)
+}
+
+// this code essentially compiles down to a noop if neither feature is enabled
+#[cfg_attr(
+    not(any(feature = "log_backend", feature = "tracing_backend")),
+    allow(unused_variables)
+)]
+fn ggml_logging_trampoline_safe(level: GGMLLogLevel, text: Cow<str>) {
+    match level {
+        GGMLLogLevel::None => {
+            // no clue what to do here, trace it?
+            generic_trace!("{}", text.trim());
+        }
+        GGMLLogLevel::Info => {
+            generic_info!("{}", text.trim());
+        }
+        GGMLLogLevel::Warn => {
+            generic_warn!("{}", text.trim());
+        }
+        GGMLLogLevel::Error => {
+            generic_error!("{}", text.trim());
+        }
+        GGMLLogLevel::Debug => {
+            generic_debug!("{}", text.trim());
+        }
+        GGMLLogLevel::Cont => {
+            // this means continue previous log
+            // storing state to do this is a massive pain so it's just a lot easier to not
+            // plus as far as i can tell it's not actually *used* anywhere
+            // ggml splits at 128 chars and doesn't actually change the kind of log
+            // so technically this is unused
+            generic_trace!("{}", text.trim());
+        }
+        GGMLLogLevel::Unknown(level) => {
+            generic_warn!(
+                "ggml_logging_trampoline: unknown log level {}: message: {}",
+                level,
+                text.trim()
+            );
+        }
+    }
+}

src/lib.rs

@@ -1,26 +1,20 @@
 #![allow(clippy::uninlined_format_args)]
 #![cfg_attr(test, feature(test))]
 
+mod common_logging;
 mod error;
+mod ggml_logging_hook;
 mod standalone;
 mod utilities;
 mod whisper_ctx;
 mod whisper_ctx_wrapper;
 mod whisper_grammar;
+mod whisper_logging_hook;
 mod whisper_params;
 mod whisper_state;
-#[cfg(feature = "whisper-cpp-log")]
-mod whisper_sys_log;
-#[cfg(feature = "whisper-cpp-tracing")]
-mod whisper_sys_tracing;
-
-#[cfg(any(feature = "whisper-cpp-log", feature = "whisper-cpp-tracing"))]
-static LOG_TRAMPOLINE_INSTALL: Once = Once::new();
 
 pub use error::WhisperError;
 pub use standalone::*;
-#[cfg(any(feature = "whisper-cpp-log", feature = "whisper-cpp-tracing"))]
-use std::sync::Once;
 pub use utilities::*;
 pub use whisper_ctx::DtwMode;
 pub use whisper_ctx::DtwModelPreset;
@@ -33,10 +27,6 @@ pub use whisper_params::{FullParams, SamplingStrategy, SegmentCallbackData};
 #[cfg(feature = "raw-api")]
 pub use whisper_rs_sys;
 pub use whisper_state::WhisperState;
-#[cfg(feature = "whisper-cpp-log")]
-pub use whisper_sys_log::install_whisper_log_trampoline;
-#[cfg(feature = "whisper-cpp-tracing")]
-pub use whisper_sys_tracing::install_whisper_tracing_trampoline;
 
 pub type WhisperSysContext = whisper_rs_sys::whisper_context;
 pub type WhisperSysState = whisper_rs_sys::whisper_state;
@@ -53,3 +43,25 @@ pub type DtwAhead = whisper_rs_sys::whisper_ahead;
 
 /// The version of whisper.cpp that whisper-rs was linked with.
 pub static WHISPER_CPP_VERSION: &str = env!("WHISPER_CPP_VERSION");
+
+/// Redirect all whisper.cpp and GGML logs to logging hooks installed by whisper-rs.
+///
+/// This will stop most logs from being output to stdout/stderr and will bring them into
+/// `log` or `tracing`, if the `log_backend` or `tracing_backend` features, respectively,
+/// are enabled. If neither is enabled, this will essentially disable logging, as they won't
+/// be output anywhere.
+///
+/// Note whisper.cpp and GGML do not reliably follow Rust logging conventions.
+/// Use your logging crate's configuration to control how these logs will be output.
+/// whisper-rs does not currently output any logs, but this may change in the future.
+/// You should configure by module path and use `whisper_rs::ggml_logging_hook`,
+/// and/or `whisper_rs::whisper_logging_hook`, to avoid possibly ignoring useful
+/// `whisper-rs` logs in the future.
+///
+/// Safe to call multiple times. Only has an effect the first time.
+/// (note this means installing your own logging handlers with unsafe functions after this call
+/// is permanent and cannot be undone)
+pub fn install_logging_hooks() {
+    crate::whisper_logging_hook::install_whisper_logging_hook();
+    crate::ggml_logging_hook::install_ggml_logging_hook();
+}

src/whisper_logging_hook.rs

@@ -0,0 +1,73 @@
+use crate::common_logging::{
+    generic_debug, generic_error, generic_info, generic_trace, generic_warn, GGMLLogLevel,
+};
+use core::ffi::{c_char, c_void};
+use std::borrow::Cow;
+use std::ffi::CStr;
+use std::sync::Once;
+use whisper_rs_sys::ggml_log_level;
+
+static WHISPER_LOG_TRAMPOLINE_INSTALL: Once = Once::new();
+pub(crate) fn install_whisper_logging_hook() {
+    WHISPER_LOG_TRAMPOLINE_INSTALL.call_once(|| unsafe {
+        whisper_rs_sys::whisper_log_set(Some(whisper_logging_trampoline), std::ptr::null_mut())
+    });
+}
+
+unsafe extern "C" fn whisper_logging_trampoline(
+    level: ggml_log_level,
+    text: *const c_char,
+    _: *mut c_void, // user_data
+) {
+    if text.is_null() {
+        generic_error!("whisper_logging_trampoline: text is nullptr");
+    }
+    let level = GGMLLogLevel::from(level);
+
+    // SAFETY: we must trust whisper.cpp that it will not pass us a string that does not satisfy
+    // from_ptr's requirements.
+    let log_str = unsafe { CStr::from_ptr(text) }.to_string_lossy();
+
+    whisper_logging_trampoline_safe(level, log_str)
+}
+
+// this code essentially compiles down to a noop if neither feature is enabled
+#[cfg_attr(
+    not(any(feature = "log_backend", feature = "tracing_backend")),
+    allow(unused_variables)
+)]
+fn whisper_logging_trampoline_safe(level: GGMLLogLevel, text: Cow<str>) {
+    match level {
+        GGMLLogLevel::None => {
+            // no clue what to do here, trace it?
+            generic_trace!("{}", text.trim());
+        }
+        GGMLLogLevel::Info => {
+            generic_info!("{}", text.trim());
+        }
+        GGMLLogLevel::Warn => {
+            generic_warn!("{}", text.trim());
+        }
+        GGMLLogLevel::Error => {
+            generic_error!("{}", text.trim());
+        }
+        GGMLLogLevel::Debug => {
+            generic_debug!("{}", text.trim());
+        }
+        GGMLLogLevel::Cont => {
+            // this means continue previous log
+            // storing state to do this is a massive pain so it's just a lot easier to not
+            // plus as far as i can tell it's not actually *used* anywhere
+            // whisper splits at 1024 chars and doesn't actually change the kind
+            // so technically this is unused
+            generic_trace!("{}", text.trim());
+        }
+        GGMLLogLevel::Unknown(level) => {
+            generic_warn!(
+                "whisper_logging_trampoline: unknown log level {}: message: {}",
+                level,
+                text.trim()
+            );
+        }
+    }
+}