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