1#![cfg_attr(
2 not(test),
3 deny(
4 clippy::expect_used,
5 clippy::indexing_slicing,
6 clippy::panic,
7 clippy::unwrap_used
8 )
9)]
10
11use std::sync::{Mutex, OnceLock};
12
13use llama_cpp_log_decoder::decode_anomaly::DecodeAnomaly;
14use llama_cpp_log_decoder::decode_output::DecodeOutput;
15use llama_cpp_log_decoder::incoming_log_level::IncomingLogLevel;
16use llama_cpp_log_decoder::log_decoder::LogDecoder;
17use llama_cpp_log_decoder::log_level::LogLevel;
18use llama_cpp_log_decoder::log_line::LogLine;
19
20use crate::log_options::LogOptions;
21
22struct LogSource {
23 decoder: Mutex<LogDecoder>,
24 target: &'static str,
25 options: LogOptions,
26}
27
28impl LogSource {
29 const fn new(target: &'static str, options: LogOptions) -> Self {
30 Self {
31 decoder: Mutex::new(LogDecoder::new()),
32 target,
33 options,
34 }
35 }
36}
37
38static LLAMA_SOURCE: OnceLock<LogSource> = OnceLock::new();
39static GGML_SOURCE: OnceLock<LogSource> = OnceLock::new();
40
41#[cfg(target_env = "msvc")]
42const fn ggml_level_to_u32(level: llama_cpp_bindings_sys::ggml_log_level) -> u32 {
43 level.cast_unsigned()
44}
45
46#[cfg(not(target_env = "msvc"))]
47const fn ggml_level_to_u32(level: llama_cpp_bindings_sys::ggml_log_level) -> u32 {
48 level
49}
50
51const fn ggml_level_to_incoming(raw: llama_cpp_bindings_sys::ggml_log_level) -> IncomingLogLevel {
52 match raw {
53 llama_cpp_bindings_sys::GGML_LOG_LEVEL_NONE => IncomingLogLevel::None,
54 llama_cpp_bindings_sys::GGML_LOG_LEVEL_DEBUG => IncomingLogLevel::Debug,
55 llama_cpp_bindings_sys::GGML_LOG_LEVEL_INFO => IncomingLogLevel::Info,
56 llama_cpp_bindings_sys::GGML_LOG_LEVEL_WARN => IncomingLogLevel::Warn,
57 llama_cpp_bindings_sys::GGML_LOG_LEVEL_ERROR => IncomingLogLevel::Error,
58 llama_cpp_bindings_sys::GGML_LOG_LEVEL_CONT => IncomingLogLevel::Cont,
59 other => IncomingLogLevel::Unknown(ggml_level_to_u32(other)),
60 }
61}
62
63fn resolve_record(line: LogLine, demote_info_to_debug: bool) -> (log::Level, String) {
64 let effective_level =
65 if demote_info_to_debug && matches!(line.level, LogLevel::Info | LogLevel::None) {
66 LogLevel::Debug
67 } else {
68 line.level
69 };
70
71 match effective_level {
72 LogLevel::Debug => (log::Level::Debug, line.text),
73 LogLevel::Info | LogLevel::None => (log::Level::Info, line.text),
74 LogLevel::Warn => (log::Level::Warn, line.text),
75 LogLevel::Error => (log::Level::Error, line.text),
76 LogLevel::Unknown(raw) => (
77 log::Level::Warn,
78 format!("[unknown level {raw}] {}", line.text),
79 ),
80 }
81}
82
83fn dispatch_line(source: &LogSource, line: LogLine) {
84 let (level, message) = resolve_record(line, source.options.demote_info_to_debug);
85 log::log!(target: source.target, level, "{message}");
86}
87
88fn dispatch_output(source: &LogSource, output: DecodeOutput) {
89 match output {
90 DecodeOutput::None => {}
91 DecodeOutput::Line(line) => dispatch_line(source, line),
92 DecodeOutput::TwoLines { earlier, current } => {
93 dispatch_line(source, earlier);
94 dispatch_line(source, current);
95 }
96 }
97}
98
99fn dispatch_anomaly(source: &LogSource, anomaly: DecodeAnomaly) {
100 log::warn!(
101 target: source.target,
102 "llama.cpp log decoder anomaly: {anomaly:?}",
103 );
104}
105
106unsafe extern "C" fn logs_to_log(
107 raw_level: llama_cpp_bindings_sys::ggml_log_level,
108 text_ptr: *const std::os::raw::c_char,
109 data_ptr: *mut std::os::raw::c_void,
110) {
111 let source: &LogSource = unsafe { &*data_ptr.cast::<LogSource>() };
112
113 if source.options.disabled {
114 return;
115 }
116
117 if text_ptr.is_null() {
118 log::warn!(
119 target: source.target,
120 "received NULL text pointer from llama.cpp log callback",
121 );
122 return;
123 }
124
125 let text_cstr = unsafe { std::ffi::CStr::from_ptr(text_ptr) };
126 let text = text_cstr.to_string_lossy();
127
128 let incoming = ggml_level_to_incoming(raw_level);
129
130 let result = {
131 let mut decoder = source
132 .decoder
133 .lock()
134 .unwrap_or_else(std::sync::PoisonError::into_inner);
135 decoder.feed(incoming, &text)
136 };
137
138 dispatch_output(source, result.output);
139
140 if let Some(anomaly) = result.anomaly {
141 dispatch_anomaly(source, anomaly);
142 }
143}
144
145pub fn send_logs_to_log(options: LogOptions) {
146 let llama_source: *const LogSource =
147 LLAMA_SOURCE.get_or_init(|| LogSource::new("llama.cpp", options.clone()));
148 let ggml_source: *const LogSource = GGML_SOURCE.get_or_init(|| LogSource::new("ggml", options));
149
150 unsafe {
151 llama_cpp_bindings_sys::llama_log_set(
152 Some(logs_to_log),
153 llama_source.cast::<std::os::raw::c_void>().cast_mut(),
154 );
155 llama_cpp_bindings_sys::ggml_log_set(
156 Some(logs_to_log),
157 ggml_source.cast::<std::os::raw::c_void>().cast_mut(),
158 );
159 }
160}
161
162#[cfg(test)]
163mod tests {
164 use std::sync::{Mutex, Once};
165
166 use llama_cpp_log_decoder::decode_output::DecodeOutput;
167 use llama_cpp_log_decoder::incoming_log_level::IncomingLogLevel;
168 use llama_cpp_log_decoder::log_level::LogLevel;
169 use llama_cpp_log_decoder::log_line::LogLine;
170 use log::{Level, Log, Metadata, Record};
171 use serial_test::serial;
172
173 use super::{
174 GGML_SOURCE, LLAMA_SOURCE, LogSource, dispatch_output, ggml_level_to_incoming, logs_to_log,
175 resolve_record, send_logs_to_log,
176 };
177 use crate::log_options::LogOptions;
178
179 #[derive(Clone, Debug)]
180 struct CapturedRecord {
181 level: Level,
182 target: String,
183 message: String,
184 }
185
186 struct TestLogger {
187 records: Mutex<Vec<CapturedRecord>>,
188 }
189
190 impl Log for TestLogger {
191 fn enabled(&self, _: &Metadata) -> bool {
192 true
193 }
194
195 fn log(&self, record: &Record) {
196 let mut guard = self
197 .records
198 .lock()
199 .unwrap_or_else(std::sync::PoisonError::into_inner);
200 guard.push(CapturedRecord {
201 level: record.level(),
202 target: record.target().to_owned(),
203 message: record.args().to_string(),
204 });
205 }
206
207 fn flush(&self) {}
208 }
209
210 static TEST_LOGGER: TestLogger = TestLogger {
211 records: Mutex::new(Vec::new()),
212 };
213 static INSTALL: Once = Once::new();
214
215 fn ensure_test_logger_installed() {
216 INSTALL.call_once(|| {
217 if log::set_logger(&TEST_LOGGER).is_ok() {
218 log::set_max_level(log::LevelFilter::Trace);
219 }
220 });
221 }
222
223 fn records_for(target: &str) -> Vec<CapturedRecord> {
224 let guard = TEST_LOGGER
225 .records
226 .lock()
227 .unwrap_or_else(std::sync::PoisonError::into_inner);
228 guard
229 .iter()
230 .filter(|record| record.target == target)
231 .cloned()
232 .collect()
233 }
234
235 fn invoke_callback(
236 level: llama_cpp_bindings_sys::ggml_log_level,
237 text: &std::ffi::CStr,
238 source: &LogSource,
239 ) {
240 let ptr = std::ptr::from_ref(source)
241 .cast::<std::os::raw::c_void>()
242 .cast_mut();
243 unsafe {
244 logs_to_log(level, text.as_ptr(), ptr);
245 }
246 }
247
248 #[test]
249 fn test_logger_enabled_and_flush() {
250 let metadata = Metadata::builder()
251 .level(Level::Info)
252 .target("test-logger-enabled")
253 .build();
254
255 assert!(TEST_LOGGER.enabled(&metadata));
256 TEST_LOGGER.flush();
257 }
258
259 #[test]
260 fn ggml_level_to_incoming_known_constants() {
261 assert_eq!(
262 ggml_level_to_incoming(llama_cpp_bindings_sys::GGML_LOG_LEVEL_NONE),
263 IncomingLogLevel::None,
264 );
265 assert_eq!(
266 ggml_level_to_incoming(llama_cpp_bindings_sys::GGML_LOG_LEVEL_DEBUG),
267 IncomingLogLevel::Debug,
268 );
269 assert_eq!(
270 ggml_level_to_incoming(llama_cpp_bindings_sys::GGML_LOG_LEVEL_INFO),
271 IncomingLogLevel::Info,
272 );
273 assert_eq!(
274 ggml_level_to_incoming(llama_cpp_bindings_sys::GGML_LOG_LEVEL_WARN),
275 IncomingLogLevel::Warn,
276 );
277 assert_eq!(
278 ggml_level_to_incoming(llama_cpp_bindings_sys::GGML_LOG_LEVEL_ERROR),
279 IncomingLogLevel::Error,
280 );
281 assert_eq!(
282 ggml_level_to_incoming(llama_cpp_bindings_sys::GGML_LOG_LEVEL_CONT),
283 IncomingLogLevel::Cont,
284 );
285 }
286
287 #[test]
288 fn ggml_level_to_incoming_unknown_value() {
289 assert_eq!(
290 ggml_level_to_incoming(9999),
291 IncomingLogLevel::Unknown(9999)
292 );
293 }
294
295 #[test]
296 fn dispatch_when_disabled() {
297 ensure_test_logger_installed();
298
299 let target = "test-dispatch-when-disabled";
300 let source = LogSource::new(target, LogOptions::default().with_logs_enabled(false));
301 invoke_callback(
302 llama_cpp_bindings_sys::GGML_LOG_LEVEL_INFO,
303 c"hello\n",
304 &source,
305 );
306
307 assert!(records_for(target).is_empty());
308 }
309
310 #[test]
311 fn demote_info_to_debug_on_info() {
312 ensure_test_logger_installed();
313
314 let target = "test-demote-info-on-info";
315 let source = LogSource::new(
316 target,
317 LogOptions::default().with_demote_info_to_debug(true),
318 );
319 invoke_callback(
320 llama_cpp_bindings_sys::GGML_LOG_LEVEL_INFO,
321 c"info-line\n",
322 &source,
323 );
324
325 assert!(records_for(target).iter().any(|record| {
326 record.level == Level::Debug && record.message.contains("info-line")
327 }));
328 }
329
330 #[test]
331 fn demote_info_to_debug_on_warn() {
332 ensure_test_logger_installed();
333
334 let target = "test-demote-info-on-warn";
335 let source = LogSource::new(
336 target,
337 LogOptions::default().with_demote_info_to_debug(true),
338 );
339 invoke_callback(
340 llama_cpp_bindings_sys::GGML_LOG_LEVEL_WARN,
341 c"warn-line\n",
342 &source,
343 );
344
345 assert!(
346 records_for(target).iter().any(|record| {
347 record.level == Level::Warn && record.message.contains("warn-line")
348 })
349 );
350 }
351
352 #[test]
353 fn dispatch_unknown_level() {
354 ensure_test_logger_installed();
355
356 let target = "test-dispatch-unknown-level";
357 let source = LogSource::new(target, LogOptions::default());
358 invoke_callback(9999, c"weird\n", &source);
359
360 assert!(records_for(target).iter().any(|record| {
361 record.level == Level::Warn
362 && record.message.contains("[unknown level 9999]")
363 && record.message.contains("weird")
364 }));
365 }
366
367 #[test]
368 fn dispatch_orphan_cont_anomaly() {
369 ensure_test_logger_installed();
370
371 let target = "test-dispatch-orphan-cont";
372 let source = LogSource::new(target, LogOptions::default());
373 invoke_callback(
374 llama_cpp_bindings_sys::GGML_LOG_LEVEL_CONT,
375 c"ghost\n",
376 &source,
377 );
378
379 assert!(records_for(target).iter().any(|record| {
380 record.level == Level::Warn && record.message.contains("OrphanCont")
381 }));
382 }
383
384 #[test]
385 fn resolve_record_error_level_maps_to_error_level() {
386 let (level, message) = resolve_record(
387 LogLine {
388 level: LogLevel::Error,
389 text: "boom".to_owned(),
390 },
391 false,
392 );
393
394 assert_eq!(level, Level::Error);
395 assert_eq!(message, "boom");
396 }
397
398 #[test]
399 fn dispatch_output_none_emits_no_records() {
400 ensure_test_logger_installed();
401
402 let target = "test-dispatch-output-none";
403 let source = LogSource::new(target, LogOptions::default());
404 dispatch_output(&source, DecodeOutput::None);
405
406 assert!(records_for(target).is_empty());
407 }
408
409 #[test]
410 fn dispatch_output_two_lines_emits_both_records() {
411 ensure_test_logger_installed();
412
413 let target = "test-dispatch-output-two-lines";
414 let source = LogSource::new(target, LogOptions::default());
415 dispatch_output(
416 &source,
417 DecodeOutput::TwoLines {
418 earlier: LogLine {
419 level: LogLevel::Info,
420 text: "earlier-line".to_owned(),
421 },
422 current: LogLine {
423 level: LogLevel::Warn,
424 text: "current-line".to_owned(),
425 },
426 },
427 );
428
429 let records = records_for(target);
430 assert!(
431 records
432 .iter()
433 .any(|record| record.message.contains("earlier-line"))
434 );
435 assert!(
436 records
437 .iter()
438 .any(|record| record.message.contains("current-line"))
439 );
440 }
441
442 #[test]
443 #[serial]
444 fn send_logs_to_log_initialization() {
445 ensure_test_logger_installed();
446 send_logs_to_log(LogOptions::default());
447
448 assert!(LLAMA_SOURCE.get().is_some());
449 assert!(GGML_SOURCE.get().is_some());
450 }
451
452 #[test]
453 fn null_text_pointer() {
454 ensure_test_logger_installed();
455
456 let target = "test-null-text-pointer";
457 let source = LogSource::new(target, LogOptions::default());
458 let source_ptr = std::ptr::from_ref(&source)
459 .cast::<std::os::raw::c_void>()
460 .cast_mut();
461 unsafe {
462 logs_to_log(
463 llama_cpp_bindings_sys::GGML_LOG_LEVEL_INFO,
464 std::ptr::null(),
465 source_ptr,
466 );
467 }
468
469 assert!(records_for(target).iter().any(|record| {
470 record.level == Level::Warn && record.message.contains("NULL text pointer")
471 }));
472 }
473
474 #[test]
475 fn decoder_mutex_poison() {
476 ensure_test_logger_installed();
477
478 let target = "test-decoder-mutex-poison";
479 let source = LogSource::new(target, LogOptions::default());
480
481 std::thread::scope(|scope| {
482 let handle = scope.spawn(|| {
483 let _guard = source
484 .decoder
485 .lock()
486 .unwrap_or_else(std::sync::PoisonError::into_inner);
487 panic!("intentional poison");
488 });
489 let _ = handle.join();
490 });
491
492 assert!(source.decoder.is_poisoned());
493
494 invoke_callback(
495 llama_cpp_bindings_sys::GGML_LOG_LEVEL_INFO,
496 c"after-poison\n",
497 &source,
498 );
499
500 assert!(
501 records_for(target)
502 .iter()
503 .any(|record| record.message.contains("after-poison"))
504 );
505 }
506}