llama_cpp_bindings/
log.rs

1use crate::log_options::LogOptions;
2use std::sync::OnceLock;
3use tracing_core::{Interest, Kind, Metadata, callsite, field, identify_callsite};
4
5static FIELD_NAMES: &[&str] = &["message", "module"];
6
7struct OverridableFields {
8    message: tracing::field::Field,
9    target: tracing::field::Field,
10}
11
12macro_rules! log_cs {
13    ($level:expr, $cs:ident, $meta:ident, $fields:ident, $ty:ident) => {
14        struct $ty;
15        static $cs: $ty = $ty;
16        static $meta: Metadata<'static> = Metadata::new(
17            "log event",
18            "llama-cpp-bindings",
19            $level,
20            ::core::option::Option::None,
21            ::core::option::Option::None,
22            ::core::option::Option::None,
23            field::FieldSet::new(FIELD_NAMES, identify_callsite!(&$cs)),
24            Kind::EVENT,
25        );
26        static $fields: std::sync::LazyLock<OverridableFields> = std::sync::LazyLock::new(|| {
27            let fields = $meta.fields();
28            OverridableFields {
29                message: fields
30                    .field("message")
31                    .expect("message field defined in FIELD_NAMES"),
32                target: fields
33                    .field("module")
34                    .expect("module field defined in FIELD_NAMES"),
35            }
36        });
37
38        impl callsite::Callsite for $ty {
39            fn set_interest(&self, _: Interest) {}
40            fn metadata(&self) -> &'static Metadata<'static> {
41                &$meta
42            }
43        }
44    };
45}
46log_cs!(
47    tracing_core::Level::DEBUG,
48    DEBUG_CS,
49    DEBUG_META,
50    DEBUG_FIELDS,
51    DebugCallsite
52);
53log_cs!(
54    tracing_core::Level::INFO,
55    INFO_CS,
56    INFO_META,
57    INFO_FIELDS,
58    InfoCallsite
59);
60log_cs!(
61    tracing_core::Level::WARN,
62    WARN_CS,
63    WARN_META,
64    WARN_FIELDS,
65    WarnCallsite
66);
67log_cs!(
68    tracing_core::Level::ERROR,
69    ERROR_CS,
70    ERROR_META,
71    ERROR_FIELDS,
72    ErrorCallsite
73);
74
75#[derive(Clone, Copy)]
76pub enum Module {
77    Ggml,
78    LlamaCpp,
79}
80
81impl Module {
82    const fn name(self) -> &'static str {
83        match self {
84            Self::Ggml => "ggml",
85            Self::LlamaCpp => "llama.cpp",
86        }
87    }
88}
89
90fn meta_for_level(
91    level: llama_cpp_bindings_sys::ggml_log_level,
92) -> Option<(&'static Metadata<'static>, &'static OverridableFields)> {
93    match level {
94        llama_cpp_bindings_sys::GGML_LOG_LEVEL_DEBUG => Some((&DEBUG_META, &DEBUG_FIELDS)),
95        llama_cpp_bindings_sys::GGML_LOG_LEVEL_INFO => Some((&INFO_META, &INFO_FIELDS)),
96        llama_cpp_bindings_sys::GGML_LOG_LEVEL_WARN => Some((&WARN_META, &WARN_FIELDS)),
97        llama_cpp_bindings_sys::GGML_LOG_LEVEL_ERROR => Some((&ERROR_META, &ERROR_FIELDS)),
98        _ => None,
99    }
100}
101
102pub struct State {
103    pub options: LogOptions,
104    module: Module,
105    buffered: std::sync::Mutex<Option<(llama_cpp_bindings_sys::ggml_log_level, String)>>,
106    previous_level: std::sync::atomic::AtomicI32,
107    is_buffering: std::sync::atomic::AtomicBool,
108}
109
110impl State {
111    #[must_use]
112    pub fn new(module: Module, options: LogOptions) -> Self {
113        Self {
114            options,
115            module,
116            buffered: std::sync::Mutex::default(),
117            previous_level: std::sync::atomic::AtomicI32::default(),
118            is_buffering: std::sync::atomic::AtomicBool::default(),
119        }
120    }
121
122    /// The match arms are duplicated per module because the `tracing` macros
123    /// require the `target` argument to be a string literal — the upstream
124    /// submodule name cannot be propagated dynamically.
125    fn generate_log(&self, level: llama_cpp_bindings_sys::ggml_log_level, text: &str) {
126        let (module, text) = text
127            .char_indices()
128            .take_while(|(_, ch)| ch.is_ascii_lowercase() || *ch == '_')
129            .last()
130            .and_then(|(pos, _)| {
131                let next_two = text.get(pos + 1..pos + 3);
132                if next_two == Some(": ") {
133                    let (sub_module, text) = text.split_at(pos + 1);
134                    let text = text.split_at(2).1;
135                    Some((Some(format!("{}::{sub_module}", self.module.name())), text))
136                } else {
137                    None
138                }
139            })
140            .unwrap_or((None, text));
141
142        let effective_level = if self.options.demote_info_to_debug
143            && (level == llama_cpp_bindings_sys::GGML_LOG_LEVEL_INFO
144                || level == llama_cpp_bindings_sys::GGML_LOG_LEVEL_DEBUG)
145        {
146            llama_cpp_bindings_sys::GGML_LOG_LEVEL_DEBUG
147        } else {
148            level
149        };
150
151        let Some((meta, fields)) = meta_for_level(effective_level) else {
152            tracing::warn!(
153                level = effective_level,
154                text = text,
155                origin = "crate",
156                "generate_log called with unmapped log level"
157            );
158
159            return;
160        };
161
162        tracing::dispatcher::get_default(|dispatcher| {
163            dispatcher.event(&tracing::Event::new(
164                meta,
165                &meta.fields().value_set(&[
166                    (&fields.message, Some(&text as &dyn tracing::field::Value)),
167                    (
168                        &fields.target,
169                        module
170                            .as_ref()
171                            .map(|module_name| module_name as &dyn tracing::field::Value),
172                    ),
173                ]),
174            ));
175        });
176    }
177
178    /// Append more text to the previously buffered log.
179    ///
180    /// The text may or may not end with a newline.
181    ///
182    /// # Panics
183    /// Panics if the internal mutex is poisoned.
184    pub fn cont_buffered_log(&self, text: &str) {
185        let mut lock = self.buffered.lock().unwrap();
186
187        if let Some((previous_log_level, mut buffer)) = lock.take() {
188            buffer.push_str(text);
189            if buffer.ends_with('\n') {
190                self.is_buffering
191                    .store(false, std::sync::atomic::Ordering::Release);
192                self.generate_log(previous_log_level, buffer.as_str());
193            } else {
194                *lock = Some((previous_log_level, buffer));
195            }
196        } else {
197            let level = self
198                .previous_level
199                .load(std::sync::atomic::Ordering::Acquire)
200                .cast_unsigned();
201            tracing::warn!(
202                inferred_level = level,
203                text = text,
204                origin = "crate",
205                "llama.cpp sent out a CONT log without any previously buffered message"
206            );
207            *lock = Some((level, text.to_string()));
208        }
209    }
210
211    /// Start buffering a message. Not the CONT log level and text is missing a newline.
212    ///
213    /// # Panics
214    /// Panics if the internal mutex is poisoned.
215    pub fn buffer_non_cont(&self, level: llama_cpp_bindings_sys::ggml_log_level, text: &str) {
216        let replaced = self
217            .buffered
218            .lock()
219            .unwrap()
220            .replace((level, text.to_string()));
221
222        if let Some((previous_log_level, buffer)) = replaced {
223            tracing::warn!(
224                level = previous_log_level,
225                text = &buffer,
226                origin = "crate",
227                "Message buffered unnecessarily due to missing newline and not followed by a CONT"
228            );
229            self.generate_log(previous_log_level, buffer.as_str());
230        }
231
232        self.is_buffering
233            .store(true, std::sync::atomic::Ordering::Release);
234        self.previous_level
235            .store(level.cast_signed(), std::sync::atomic::Ordering::Release);
236    }
237
238    /// Emit a normal unbuffered log message (not the CONT log level and the text ends with a newline).
239    ///
240    /// # Panics
241    /// Panics if the internal mutex is poisoned.
242    pub fn emit_non_cont_line(&self, level: llama_cpp_bindings_sys::ggml_log_level, text: &str) {
243        if self
244            .is_buffering
245            .swap(false, std::sync::atomic::Ordering::Acquire)
246            && let Some((buf_level, buf_text)) = self.buffered.lock().unwrap().take()
247        {
248            tracing::warn!(
249                level = buf_level,
250                text = buf_text,
251                origin = "crate",
252                "llama.cpp message buffered spuriously due to missing \\n and being followed by a non-CONT message! (this indicates a bug within llama.cpp)"
253            );
254            self.generate_log(buf_level, buf_text.as_str());
255        }
256
257        self.previous_level
258            .store(level.cast_signed(), std::sync::atomic::Ordering::Release);
259
260        let (text, _trailing_newline) = text.split_at(text.len() - 1);
261
262        match level {
263            llama_cpp_bindings_sys::GGML_LOG_LEVEL_NONE => {
264                if self.options.demote_info_to_debug {
265                    self.generate_log(llama_cpp_bindings_sys::GGML_LOG_LEVEL_DEBUG, text);
266                } else {
267                    tracing::info!(no_log_level = true, text);
268                }
269            }
270            llama_cpp_bindings_sys::GGML_LOG_LEVEL_DEBUG
271            | llama_cpp_bindings_sys::GGML_LOG_LEVEL_INFO
272            | llama_cpp_bindings_sys::GGML_LOG_LEVEL_WARN
273            | llama_cpp_bindings_sys::GGML_LOG_LEVEL_ERROR => self.generate_log(level, text),
274            llama_cpp_bindings_sys::GGML_LOG_LEVEL_CONT => {
275                tracing::warn!(
276                    text = text,
277                    origin = "crate",
278                    "CONT log level passed to emit_non_cont_line"
279                );
280            }
281            _ => {
282                tracing::warn!(
283                    level = level,
284                    text = text,
285                    origin = "crate",
286                    "Unknown llama.cpp log level"
287                );
288            }
289        }
290    }
291
292    pub fn update_previous_level_for_disabled_log(
293        &self,
294        level: llama_cpp_bindings_sys::ggml_log_level,
295    ) {
296        if level != llama_cpp_bindings_sys::GGML_LOG_LEVEL_CONT {
297            self.previous_level
298                .store(level.cast_signed(), std::sync::atomic::Ordering::Release);
299        }
300    }
301
302    /// Checks whether the given log level is enabled by the current tracing
303    /// subscriber. CONT lines inherit the previous line's level rather than
304    /// being checked on their own.
305    pub fn is_enabled_for_level(&self, level: llama_cpp_bindings_sys::ggml_log_level) -> bool {
306        let level = if level == llama_cpp_bindings_sys::GGML_LOG_LEVEL_CONT {
307            self.previous_level
308                .load(std::sync::atomic::Ordering::Relaxed)
309                .cast_unsigned()
310        } else {
311            level
312        };
313
314        let effective_level = if self.options.demote_info_to_debug
315            && (level == llama_cpp_bindings_sys::GGML_LOG_LEVEL_INFO
316                || level == llama_cpp_bindings_sys::GGML_LOG_LEVEL_DEBUG)
317        {
318            llama_cpp_bindings_sys::GGML_LOG_LEVEL_DEBUG
319        } else {
320            level
321        };
322
323        let Some((meta, _)) = meta_for_level(effective_level) else {
324            return false;
325        };
326
327        tracing::dispatcher::get_default(|dispatcher| dispatcher.enabled(meta))
328    }
329}
330
331pub static LLAMA_STATE: OnceLock<Box<State>> = OnceLock::new();
332pub static GGML_STATE: OnceLock<Box<State>> = OnceLock::new();
333
334/// Bridges llama.cpp / ggml log callbacks into the `tracing` ecosystem.
335///
336/// The fast path — newline-terminated DEBUG/INFO/WARN/ERROR lines — must avoid
337/// taking the log state lock and must not allocate, so the buffering and
338/// CONT-handling logic only runs on the slow path. Lines that lack a trailing
339/// newline are buffered: their absence is the only signal upstream uses to
340/// announce that a CONT message will follow, and we cannot distinguish that
341/// from a typo until the next message arrives.
342extern "C" fn logs_to_trace(
343    level: llama_cpp_bindings_sys::ggml_log_level,
344    text: *const ::std::os::raw::c_char,
345    data: *mut ::std::os::raw::c_void,
346) {
347    use std::borrow::Borrow;
348
349    let log_state = unsafe { &*(data as *const State) };
350
351    if log_state.options.disabled {
352        return;
353    }
354
355    if !log_state.is_enabled_for_level(level) {
356        log_state.update_previous_level_for_disabled_log(level);
357
358        return;
359    }
360
361    let text = unsafe { std::ffi::CStr::from_ptr(text) };
362    let text = text.to_string_lossy();
363    let text: &str = text.borrow();
364
365    if level == llama_cpp_bindings_sys::GGML_LOG_LEVEL_CONT {
366        log_state.cont_buffered_log(text);
367    } else if text.ends_with('\n') {
368        log_state.emit_non_cont_line(level, text);
369    } else {
370        log_state.buffer_non_cont(level, text);
371    }
372}
373
374/// Redirect llama.cpp logs into tracing.
375///
376/// `llama.cpp` and `ggml` are wired up to separate `State` instances so a CONT
377/// line emitted by one cannot be appended to a buffered line from the other.
378/// `llama_log_set` also installs the callback for `ggml`, so the `ggml_log_set`
379/// call must come second to override that and bind the ggml state explicitly.
380pub fn send_logs_to_tracing(options: LogOptions) {
381    let llama_heap_state = Box::as_ref(
382        LLAMA_STATE.get_or_init(|| Box::new(State::new(Module::LlamaCpp, options.clone()))),
383    ) as *const _;
384    let ggml_heap_state =
385        Box::as_ref(GGML_STATE.get_or_init(|| Box::new(State::new(Module::Ggml, options))))
386            as *const _;
387
388    unsafe {
389        llama_cpp_bindings_sys::llama_log_set(Some(logs_to_trace), llama_heap_state as *mut _);
390        llama_cpp_bindings_sys::ggml_log_set(Some(logs_to_trace), ggml_heap_state as *mut _);
391    }
392}
393
394#[cfg(test)]
395mod tests {
396    use std::sync::{Arc, Mutex};
397
398    use tracing_subscriber::util::SubscriberInitExt;
399
400    use super::{Module, State, logs_to_trace};
401    use crate::log_options::LogOptions;
402
403    #[test]
404    fn module_name_ggml() {
405        assert_eq!(Module::Ggml.name(), "ggml");
406    }
407
408    #[test]
409    fn module_name_llama_cpp() {
410        assert_eq!(Module::LlamaCpp.name(), "llama.cpp");
411    }
412
413    #[test]
414    fn state_new_creates_empty_buffer() {
415        let state = State::new(Module::LlamaCpp, LogOptions::default());
416        let buffer = state
417            .buffered
418            .lock()
419            .unwrap_or_else(std::sync::PoisonError::into_inner);
420
421        assert!(buffer.is_none());
422        drop(buffer);
423        assert!(!state.options.disabled);
424    }
425
426    #[test]
427    fn update_previous_level_for_disabled_log_stores_level() {
428        let state = State::new(Module::LlamaCpp, LogOptions::default());
429
430        state.update_previous_level_for_disabled_log(llama_cpp_bindings_sys::GGML_LOG_LEVEL_WARN);
431
432        let stored = state
433            .previous_level
434            .load(std::sync::atomic::Ordering::Relaxed);
435
436        assert_eq!(
437            stored,
438            llama_cpp_bindings_sys::GGML_LOG_LEVEL_WARN.cast_signed()
439        );
440    }
441
442    #[test]
443    fn update_previous_level_ignores_cont() {
444        let state = State::new(Module::LlamaCpp, LogOptions::default());
445
446        state.update_previous_level_for_disabled_log(llama_cpp_bindings_sys::GGML_LOG_LEVEL_ERROR);
447        state.update_previous_level_for_disabled_log(llama_cpp_bindings_sys::GGML_LOG_LEVEL_CONT);
448
449        let stored = state
450            .previous_level
451            .load(std::sync::atomic::Ordering::Relaxed);
452
453        assert_eq!(
454            stored,
455            llama_cpp_bindings_sys::GGML_LOG_LEVEL_ERROR.cast_signed()
456        );
457    }
458
459    #[test]
460    fn buffer_non_cont_sets_buffering_flag() {
461        let state = State::new(Module::LlamaCpp, LogOptions::default());
462
463        state.buffer_non_cont(llama_cpp_bindings_sys::GGML_LOG_LEVEL_INFO, "partial");
464
465        assert!(
466            state
467                .is_buffering
468                .load(std::sync::atomic::Ordering::Relaxed)
469        );
470
471        let buffer = state
472            .buffered
473            .lock()
474            .unwrap_or_else(std::sync::PoisonError::into_inner);
475
476        assert!(buffer.is_some());
477        let (level, text) = buffer.as_ref().unwrap();
478        assert_eq!(*level, llama_cpp_bindings_sys::GGML_LOG_LEVEL_INFO);
479        assert_eq!(text, "partial");
480        drop(buffer);
481    }
482
483    #[test]
484    fn cont_buffered_log_appends_to_existing_buffer() {
485        let state = State::new(Module::LlamaCpp, LogOptions::default());
486
487        state.buffer_non_cont(llama_cpp_bindings_sys::GGML_LOG_LEVEL_INFO, "hello ");
488
489        state.cont_buffered_log("world");
490
491        let buffer = state
492            .buffered
493            .lock()
494            .unwrap_or_else(std::sync::PoisonError::into_inner);
495
496        assert!(buffer.is_some());
497        let (_, text) = buffer.as_ref().unwrap();
498        assert_eq!(text, "hello world");
499        drop(buffer);
500    }
501
502    struct Logger {
503        #[expect(
504            unused,
505            reason = "guard must outlive the test body so the tracing subscriber stays installed; \
506                      dropping it un-installs the subscriber and tests would silently miss log lines"
507        )]
508        guard: tracing::subscriber::DefaultGuard,
509        logs: Arc<Mutex<Vec<String>>>,
510    }
511
512    #[derive(Clone)]
513    struct VecWriter(Arc<Mutex<Vec<String>>>);
514
515    impl std::io::Write for VecWriter {
516        fn write(&mut self, buf: &[u8]) -> std::io::Result<usize> {
517            let log_line = String::from_utf8_lossy(buf).into_owned();
518            self.0.lock().unwrap().push(log_line);
519
520            Ok(buf.len())
521        }
522
523        fn flush(&mut self) -> std::io::Result<()> {
524            Ok(())
525        }
526    }
527
528    fn create_logger(max_level: tracing::Level) -> Logger {
529        let logs = Arc::new(Mutex::new(vec![]));
530        let writer = VecWriter(logs.clone());
531
532        Logger {
533            guard: tracing_subscriber::fmt()
534                .with_max_level(max_level)
535                .with_ansi(false)
536                .without_time()
537                .with_file(false)
538                .with_line_number(false)
539                .with_level(false)
540                .with_target(false)
541                .with_writer(move || writer.clone())
542                .finish()
543                .set_default(),
544            logs,
545        }
546    }
547
548    #[test]
549    fn cont_disabled_log() {
550        let logger = create_logger(tracing::Level::INFO);
551        let mut log_state = Box::new(State::new(Module::LlamaCpp, LogOptions::default()));
552        let log_ptr =
553            std::ptr::from_mut::<State>(log_state.as_mut()).cast::<std::os::raw::c_void>();
554
555        logs_to_trace(
556            llama_cpp_bindings_sys::GGML_LOG_LEVEL_DEBUG,
557            c"Hello ".as_ptr(),
558            log_ptr,
559        );
560        logs_to_trace(
561            llama_cpp_bindings_sys::GGML_LOG_LEVEL_CONT,
562            c"world\n".as_ptr(),
563            log_ptr,
564        );
565
566        assert!(logger.logs.lock().unwrap().is_empty());
567
568        logs_to_trace(
569            llama_cpp_bindings_sys::GGML_LOG_LEVEL_DEBUG,
570            c"Hello ".as_ptr(),
571            log_ptr,
572        );
573        logs_to_trace(
574            llama_cpp_bindings_sys::GGML_LOG_LEVEL_CONT,
575            c"world".as_ptr(),
576            log_ptr,
577        );
578        logs_to_trace(
579            llama_cpp_bindings_sys::GGML_LOG_LEVEL_CONT,
580            c"\n".as_ptr(),
581            log_ptr,
582        );
583    }
584
585    #[test]
586    fn cont_message_concatenates_payload_then_flush_appends_extra_newline() {
587        let logger = create_logger(tracing::Level::INFO);
588        let mut log_state = Box::new(State::new(Module::LlamaCpp, LogOptions::default()));
589        let log_ptr =
590            std::ptr::from_mut::<State>(log_state.as_mut()).cast::<std::os::raw::c_void>();
591
592        logs_to_trace(
593            llama_cpp_bindings_sys::GGML_LOG_LEVEL_INFO,
594            c"Hello ".as_ptr(),
595            log_ptr,
596        );
597        let cont_payload_with_newline = c"world\n";
598        logs_to_trace(
599            llama_cpp_bindings_sys::GGML_LOG_LEVEL_CONT,
600            cont_payload_with_newline.as_ptr(),
601            log_ptr,
602        );
603
604        let payload_newline = '\n';
605        let flush_appended_newline = '\n';
606        assert_eq!(
607            *logger.logs.lock().unwrap(),
608            vec![format!(
609                "Hello world{payload_newline}{flush_appended_newline}"
610            )]
611        );
612    }
613
614    #[test]
615    fn disabled_logs_are_suppressed() {
616        let logger = create_logger(tracing::Level::DEBUG);
617        let disabled_options = LogOptions::default().with_logs_enabled(false);
618        let mut log_state = Box::new(State::new(Module::LlamaCpp, disabled_options));
619        let log_ptr =
620            std::ptr::from_mut::<State>(log_state.as_mut()).cast::<std::os::raw::c_void>();
621
622        logs_to_trace(
623            llama_cpp_bindings_sys::GGML_LOG_LEVEL_INFO,
624            c"Should not appear\n".as_ptr(),
625            log_ptr,
626        );
627        logs_to_trace(
628            llama_cpp_bindings_sys::GGML_LOG_LEVEL_ERROR,
629            c"Also suppressed\n".as_ptr(),
630            log_ptr,
631        );
632
633        assert!(logger.logs.lock().unwrap().is_empty());
634    }
635
636    #[test]
637    fn info_level_log_emitted() {
638        let logger = create_logger(tracing::Level::INFO);
639        let mut log_state = Box::new(State::new(Module::LlamaCpp, LogOptions::default()));
640        let log_ptr =
641            std::ptr::from_mut::<State>(log_state.as_mut()).cast::<std::os::raw::c_void>();
642
643        logs_to_trace(
644            llama_cpp_bindings_sys::GGML_LOG_LEVEL_INFO,
645            c"info message\n".as_ptr(),
646            log_ptr,
647        );
648
649        let logs = logger.logs.lock().unwrap();
650        assert_eq!(logs.len(), 1);
651        assert!(logs[0].contains("info message"));
652        drop(logs);
653    }
654
655    #[test]
656    fn warn_level_log_emitted() {
657        let logger = create_logger(tracing::Level::WARN);
658        let mut log_state = Box::new(State::new(Module::LlamaCpp, LogOptions::default()));
659        let log_ptr =
660            std::ptr::from_mut::<State>(log_state.as_mut()).cast::<std::os::raw::c_void>();
661
662        logs_to_trace(
663            llama_cpp_bindings_sys::GGML_LOG_LEVEL_WARN,
664            c"warning message\n".as_ptr(),
665            log_ptr,
666        );
667
668        let logs = logger.logs.lock().unwrap();
669        assert_eq!(logs.len(), 1);
670        assert!(logs[0].contains("warning message"));
671        drop(logs);
672    }
673
674    #[test]
675    fn error_level_log_emitted() {
676        let logger = create_logger(tracing::Level::ERROR);
677        let mut log_state = Box::new(State::new(Module::LlamaCpp, LogOptions::default()));
678        let log_ptr =
679            std::ptr::from_mut::<State>(log_state.as_mut()).cast::<std::os::raw::c_void>();
680
681        logs_to_trace(
682            llama_cpp_bindings_sys::GGML_LOG_LEVEL_ERROR,
683            c"error message\n".as_ptr(),
684            log_ptr,
685        );
686
687        let logs = logger.logs.lock().unwrap();
688        assert_eq!(logs.len(), 1);
689        assert!(logs[0].contains("error message"));
690        drop(logs);
691    }
692
693    #[test]
694    fn debug_level_log_emitted_when_enabled() {
695        let logger = create_logger(tracing::Level::DEBUG);
696        let mut log_state = Box::new(State::new(Module::LlamaCpp, LogOptions::default()));
697        let log_ptr =
698            std::ptr::from_mut::<State>(log_state.as_mut()).cast::<std::os::raw::c_void>();
699
700        logs_to_trace(
701            llama_cpp_bindings_sys::GGML_LOG_LEVEL_DEBUG,
702            c"debug message\n".as_ptr(),
703            log_ptr,
704        );
705
706        let logs = logger.logs.lock().unwrap();
707        assert_eq!(logs.len(), 1);
708        assert!(logs[0].contains("debug message"));
709        drop(logs);
710    }
711
712    #[test]
713    fn submodule_extraction_from_log_text() {
714        let logger = create_logger(tracing::Level::INFO);
715        let mut log_state = Box::new(State::new(Module::LlamaCpp, LogOptions::default()));
716        let log_ptr =
717            std::ptr::from_mut::<State>(log_state.as_mut()).cast::<std::os::raw::c_void>();
718
719        logs_to_trace(
720            llama_cpp_bindings_sys::GGML_LOG_LEVEL_INFO,
721            c"sampling: initialized\n".as_ptr(),
722            log_ptr,
723        );
724
725        let logs = logger.logs.lock().unwrap();
726        assert_eq!(logs.len(), 1);
727        assert!(logs[0].contains("initialized"));
728        drop(logs);
729    }
730
731    #[test]
732    fn multi_part_cont_log() {
733        let logger = create_logger(tracing::Level::INFO);
734        let mut log_state = Box::new(State::new(Module::LlamaCpp, LogOptions::default()));
735        let log_ptr =
736            std::ptr::from_mut::<State>(log_state.as_mut()).cast::<std::os::raw::c_void>();
737
738        logs_to_trace(
739            llama_cpp_bindings_sys::GGML_LOG_LEVEL_INFO,
740            c"part1 ".as_ptr(),
741            log_ptr,
742        );
743        logs_to_trace(
744            llama_cpp_bindings_sys::GGML_LOG_LEVEL_CONT,
745            c"part2 ".as_ptr(),
746            log_ptr,
747        );
748        logs_to_trace(
749            llama_cpp_bindings_sys::GGML_LOG_LEVEL_CONT,
750            c"part3\n".as_ptr(),
751            log_ptr,
752        );
753
754        let logs = logger.logs.lock().unwrap();
755        assert_eq!(logs.len(), 1);
756        assert!(logs[0].contains("part1 part2 part3"));
757        drop(logs);
758    }
759
760    #[test]
761    fn demote_info_to_debug_suppresses_info_under_info_subscriber() {
762        let logger = create_logger(tracing::Level::INFO);
763        let options = LogOptions::default().with_demote_info_to_debug(true);
764        let mut log_state = Box::new(State::new(Module::LlamaCpp, options));
765        let log_ptr =
766            std::ptr::from_mut::<State>(log_state.as_mut()).cast::<std::os::raw::c_void>();
767
768        logs_to_trace(
769            llama_cpp_bindings_sys::GGML_LOG_LEVEL_INFO,
770            c"should be suppressed\n".as_ptr(),
771            log_ptr,
772        );
773
774        assert!(logger.logs.lock().unwrap().is_empty());
775    }
776
777    #[test]
778    fn demote_info_to_debug_emits_info_under_debug_subscriber() {
779        let logger = create_logger(tracing::Level::DEBUG);
780        let options = LogOptions::default().with_demote_info_to_debug(true);
781        let mut log_state = Box::new(State::new(Module::LlamaCpp, options));
782        let log_ptr =
783            std::ptr::from_mut::<State>(log_state.as_mut()).cast::<std::os::raw::c_void>();
784
785        logs_to_trace(
786            llama_cpp_bindings_sys::GGML_LOG_LEVEL_INFO,
787            c"visible at debug\n".as_ptr(),
788            log_ptr,
789        );
790
791        let logs = logger.logs.lock().unwrap();
792        assert_eq!(logs.len(), 1);
793        assert!(logs[0].contains("visible at debug"));
794        drop(logs);
795    }
796
797    #[test]
798    fn demote_info_to_debug_preserves_error_under_info_subscriber() {
799        let logger = create_logger(tracing::Level::INFO);
800        let options = LogOptions::default().with_demote_info_to_debug(true);
801        let mut log_state = Box::new(State::new(Module::LlamaCpp, options));
802        let log_ptr =
803            std::ptr::from_mut::<State>(log_state.as_mut()).cast::<std::os::raw::c_void>();
804
805        logs_to_trace(
806            llama_cpp_bindings_sys::GGML_LOG_LEVEL_ERROR,
807            c"error still visible\n".as_ptr(),
808            log_ptr,
809        );
810
811        let logs = logger.logs.lock().unwrap();
812        assert_eq!(logs.len(), 1);
813        assert!(logs[0].contains("error still visible"));
814        drop(logs);
815    }
816
817    #[test]
818    fn demote_info_to_debug_preserves_warn_under_info_subscriber() {
819        let logger = create_logger(tracing::Level::INFO);
820        let options = LogOptions::default().with_demote_info_to_debug(true);
821        let mut log_state = Box::new(State::new(Module::LlamaCpp, options));
822        let log_ptr =
823            std::ptr::from_mut::<State>(log_state.as_mut()).cast::<std::os::raw::c_void>();
824
825        logs_to_trace(
826            llama_cpp_bindings_sys::GGML_LOG_LEVEL_WARN,
827            c"warning still visible\n".as_ptr(),
828            log_ptr,
829        );
830
831        let logs = logger.logs.lock().unwrap();
832        assert_eq!(logs.len(), 1);
833        assert!(logs[0].contains("warning still visible"));
834        drop(logs);
835    }
836
837    #[test]
838    fn emit_non_cont_line_level_none() {
839        let logger = create_logger(tracing::Level::INFO);
840        let state = State::new(Module::LlamaCpp, LogOptions::default());
841
842        state.emit_non_cont_line(
843            llama_cpp_bindings_sys::GGML_LOG_LEVEL_NONE,
844            "none level message\n",
845        );
846
847        let logs = logger.logs.lock().unwrap();
848        assert_eq!(logs.len(), 1);
849        assert!(logs[0].contains("none level message"));
850        drop(logs);
851    }
852
853    #[test]
854    fn emit_non_cont_line_level_none_demoted_to_debug() {
855        let logger = create_logger(tracing::Level::DEBUG);
856        let options = LogOptions::default().with_demote_info_to_debug(true);
857        let state = State::new(Module::LlamaCpp, options);
858
859        state.emit_non_cont_line(
860            llama_cpp_bindings_sys::GGML_LOG_LEVEL_NONE,
861            "demoted none\n",
862        );
863
864        let logs = logger.logs.lock().unwrap();
865        assert_eq!(logs.len(), 1);
866        assert!(logs[0].contains("demoted none"));
867        drop(logs);
868    }
869
870    #[test]
871    fn cont_without_prior_buffer_infers_level() {
872        let _logger = create_logger(tracing::Level::WARN);
873        let state = State::new(Module::LlamaCpp, LogOptions::default());
874
875        state.update_previous_level_for_disabled_log(llama_cpp_bindings_sys::GGML_LOG_LEVEL_WARN);
876        state.cont_buffered_log("orphan text");
877
878        let buffer = state.buffered.lock().unwrap();
879        assert!(buffer.is_some());
880        let (level, text) = buffer.as_ref().unwrap();
881        assert_eq!(*level, llama_cpp_bindings_sys::GGML_LOG_LEVEL_WARN);
882        assert_eq!(text, "orphan text");
883        drop(buffer);
884    }
885
886    #[test]
887    fn emit_non_cont_flushes_stale_buffer() {
888        let _logger = create_logger(tracing::Level::WARN);
889        let state = State::new(Module::LlamaCpp, LogOptions::default());
890
891        state.buffer_non_cont(llama_cpp_bindings_sys::GGML_LOG_LEVEL_INFO, "stale");
892
893        state.emit_non_cont_line(llama_cpp_bindings_sys::GGML_LOG_LEVEL_WARN, "new line\n");
894
895        let buffer = state.buffered.lock().unwrap();
896        assert!(buffer.is_none());
897        drop(buffer);
898    }
899
900    #[test]
901    fn buffer_non_cont_replaces_previous_buffer() {
902        let _logger = create_logger(tracing::Level::WARN);
903        let state = State::new(Module::LlamaCpp, LogOptions::default());
904
905        state.buffer_non_cont(llama_cpp_bindings_sys::GGML_LOG_LEVEL_INFO, "first");
906        state.buffer_non_cont(llama_cpp_bindings_sys::GGML_LOG_LEVEL_WARN, "second");
907
908        let buffer = state.buffered.lock().unwrap();
909        let (level, text) = buffer.as_ref().unwrap();
910        assert_eq!(*level, llama_cpp_bindings_sys::GGML_LOG_LEVEL_WARN);
911        assert_eq!(text, "second");
912        drop(buffer);
913    }
914
915    #[test]
916    fn is_enabled_for_cont_uses_previous_level() {
917        let _logger = create_logger(tracing::Level::WARN);
918        let state = State::new(Module::LlamaCpp, LogOptions::default());
919
920        state.update_previous_level_for_disabled_log(llama_cpp_bindings_sys::GGML_LOG_LEVEL_ERROR);
921
922        let enabled = state.is_enabled_for_level(llama_cpp_bindings_sys::GGML_LOG_LEVEL_CONT);
923
924        assert!(enabled);
925    }
926
927    #[test]
928    fn unknown_log_level_emits_warning() {
929        let logger = create_logger(tracing::Level::WARN);
930        let state = State::new(Module::LlamaCpp, LogOptions::default());
931
932        state.emit_non_cont_line(9999, "unknown level message\n");
933
934        let logs = logger.logs.lock().unwrap();
935        assert!(
936            logs.iter()
937                .any(|log_line| log_line.contains("Unknown llama.cpp log level"))
938        );
939        drop(logs);
940    }
941
942    #[test]
943    fn send_logs_to_tracing_initializes_global_states() {
944        use super::{GGML_STATE, LLAMA_STATE, send_logs_to_tracing};
945
946        send_logs_to_tracing(LogOptions::default());
947
948        assert!(LLAMA_STATE.get().is_some());
949        assert!(GGML_STATE.get().is_some());
950    }
951
952    #[test]
953    fn meta_for_level_returns_none_for_unknown_level() {
954        let result = super::meta_for_level(9999);
955
956        assert!(result.is_none());
957    }
958
959    #[test]
960    fn is_enabled_for_level_returns_false_for_none_level() {
961        let _logger = create_logger(tracing::Level::DEBUG);
962        let state = State::new(Module::LlamaCpp, LogOptions::default());
963
964        let enabled = state.is_enabled_for_level(llama_cpp_bindings_sys::GGML_LOG_LEVEL_NONE);
965
966        assert!(!enabled);
967    }
968
969    #[test]
970    fn generate_log_handles_unmapped_level_gracefully() {
971        let _logger = create_logger(tracing::Level::WARN);
972        let state = State::new(Module::LlamaCpp, LogOptions::default());
973
974        state.generate_log(9999, "unmapped level message");
975    }
976
977    #[test]
978    fn emit_non_cont_line_handles_cont_level_gracefully() {
979        let _logger = create_logger(tracing::Level::WARN);
980        let state = State::new(Module::LlamaCpp, LogOptions::default());
981
982        state.emit_non_cont_line(
983            llama_cpp_bindings_sys::GGML_LOG_LEVEL_CONT,
984            "cont passed to non-cont\n",
985        );
986    }
987
988    #[test]
989    fn callsite_metadata_returns_static_metadata() {
990        use tracing_core::callsite::Callsite;
991
992        let debug_meta = super::DEBUG_CS.metadata();
993        let info_meta = super::INFO_CS.metadata();
994        let warn_meta = super::WARN_CS.metadata();
995        let error_meta = super::ERROR_CS.metadata();
996
997        assert_eq!(*debug_meta.level(), tracing_core::Level::DEBUG);
998        assert_eq!(*info_meta.level(), tracing_core::Level::INFO);
999        assert_eq!(*warn_meta.level(), tracing_core::Level::WARN);
1000        assert_eq!(*error_meta.level(), tracing_core::Level::ERROR);
1001    }
1002
1003    #[test]
1004    fn callsite_set_interest_does_not_panic() {
1005        use tracing_core::callsite::Callsite;
1006        use tracing_core::subscriber::Interest;
1007
1008        super::DEBUG_CS.set_interest(Interest::always());
1009        super::INFO_CS.set_interest(Interest::never());
1010        super::WARN_CS.set_interest(Interest::sometimes());
1011        super::ERROR_CS.set_interest(Interest::always());
1012    }
1013
1014    #[test]
1015    fn vec_writer_flush_succeeds() {
1016        use std::io::Write;
1017
1018        let mut writer = VecWriter(Arc::new(Mutex::new(vec![])));
1019
1020        writer.flush().unwrap();
1021    }
1022}
llama_cpp_bindings/log.rs

llama_cpp_bindings/
log.rs
