matrixcode_core/
debug.rs

1//! Debug logging for MatrixCode operations
2//!
3//! Tracks: API calls, compression, memory saves, tool executions
4//!
5//! Features:
6//! - Debug mode toggle: only logs when debug mode is enabled
7//! - Session-based files: each session gets its own log file
8//! - Auto rotation: rotates when file exceeds size limit
9
10use std::fs::{self, File, OpenOptions};
11use std::io::Write;
12use std::path::PathBuf;
13use std::sync::atomic::{AtomicBool, AtomicU64, Ordering};
14use std::sync::Mutex;
15use std::time::{SystemTime, UNIX_EPOCH};
16
17use crate::truncate::truncate_with_suffix;
18use crate::event::AgentEvent;
19use crate::constants::MATRIX_DIR;
20use tokio::sync::mpsc;
21
22static API_CALL_COUNT: AtomicU64 = AtomicU64::new(0);
23static COMPRESSION_COUNT: AtomicU64 = AtomicU64::new(0);
24static MEMORY_SAVE_COUNT: AtomicU64 = AtomicU64::new(0);
25static TOOL_CALL_COUNT: AtomicU64 = AtomicU64::new(0);
26
27/// Maximum log file size before rotation (10 MB)
28const MAX_LOG_SIZE: u64 = 10 * 1024 * 1024;
29
30/// Debug logger that writes to file
31pub struct DebugLog {
32    file: Mutex<Option<File>>,
33    current_file: Mutex<Option<PathBuf>>,
34    enabled: AtomicBool,
35    session_id: Mutex<Option<String>>,
36}
37
38impl Default for DebugLog {
39    fn default() -> Self {
40        Self::new()
41    }
42}
43
44impl DebugLog {
45    /// Create a new debug logger
46    /// Initially disabled, call enable() to start logging
47    pub fn new() -> Self {
48        Self {
49            file: Mutex::new(None),
50            current_file: Mutex::new(None),
51            enabled: AtomicBool::new(false),
52            session_id: Mutex::new(None),
53        }
54    }
55
56    /// Enable debug logging with a session ID
57    /// Creates a session-specific log file
58    pub fn enable(&self, session_id: Option<&str>) {
59        self.enabled.store(true, Ordering::Relaxed);
60
61        // Generate session ID if not provided
62        let sid = session_id.map(|s| s.to_string()).unwrap_or_else(|| {
63            Self::generate_session_id()
64        });
65
66        if let Ok(mut guard) = self.session_id.lock() {
67            *guard = Some(sid.clone());
68        }
69
70        // Create new log file for this session
71        if let Ok(mut file_guard) = self.file.lock() {
72            if let Ok(mut path_guard) = self.current_file.lock() {
73                match Self::open_session_log_file(&sid, 0) {
74                    Ok((file, path)) => {
75                        *file_guard = Some(file);
76                        *path_guard = Some(path);
77                    }
78                    Err(e) => {
79                        eprintln!("Failed to create debug log file: {}", e);
80                    }
81                }
82            }
83        }
84    }
85
86    /// Disable debug logging
87    pub fn disable(&self) {
88        self.enabled.store(false, Ordering::Relaxed);
89        if let Ok(mut guard) = self.file.lock() {
90            *guard = None;
91        }
92    }
93
94    /// Check if debug logging is enabled
95    pub fn is_enabled(&self) -> bool {
96        self.enabled.load(Ordering::Relaxed)
97    }
98
99    /// Generate a timestamp-based session ID
100    fn generate_session_id() -> String {
101        let now = SystemTime::now()
102            .duration_since(UNIX_EPOCH)
103            .unwrap_or_default()
104            .as_secs();
105        format!("session_{}", now)
106    }
107
108    /// Get log directory path
109    fn get_log_dir() -> Result<PathBuf, std::io::Error> {
110        let home = std::env::var_os("HOME")
111            .or_else(|| std::env::var_os("USERPROFILE"))
112            .ok_or_else(|| std::io::Error::new(std::io::ErrorKind::NotFound, "HOME not set"))?;
113        let mut path = PathBuf::from(home);
114        path.push(MATRIX_DIR);
115        path.push("logs");
116        fs::create_dir_all(&path)?;
117        Ok(path)
118    }
119
120    /// Open a session-specific log file
121    fn open_session_log_file(session_id: &str, rotation: u32) -> Result<(File, PathBuf), std::io::Error> {
122        let mut path = Self::get_log_dir()?;
123        let filename = if rotation == 0 {
124            format!("{}.log", session_id)
125        } else {
126            format!("{}.{}.log", session_id, rotation)
127        };
128        path.push(&filename);
129        let file = OpenOptions::new()
130            .create(true)
131            .append(true)
132            .open(&path)?;
133        Ok((file, path))
134    }
135
136    /// Rotate log file if it exceeds size limit
137    fn rotate_if_needed(&self) {
138        if let Ok(mut file_guard) = self.file.lock()
139            && let Ok(mut path_guard) = self.current_file.lock()
140            && let Ok(session_guard) = self.session_id.lock()
141        {
142            if let (Some(file), Some(_path), Some(session_id)) =
143                (file_guard.as_mut(), path_guard.as_ref(), session_guard.as_ref())
144            {
145                // Check file size
146                if let Ok(metadata) = file.metadata() {
147                    if metadata.len() > MAX_LOG_SIZE {
148                        // Find next available rotation number
149                        let mut rotation = 1u32;
150                        loop {
151                            let mut new_path = Self::get_log_dir().unwrap_or_default();
152                            let filename = format!("{}.{}.log", session_id, rotation);
153                            new_path.push(&filename);
154                            if !new_path.exists() {
155                                break;
156                            }
157                            rotation += 1;
158                        }
159
160                        // Open new rotated file
161                        if let Ok((new_file, new_path)) = Self::open_session_log_file(session_id, rotation) {
162                            *file_guard = Some(new_file);
163                            *path_guard = Some(new_path);
164                        }
165                    }
166                }
167            }
168        }
169    }
170
171    /// Clean up old log files (keep last N sessions)
172    pub fn cleanup_old_logs(keep_count: usize) -> Result<(), std::io::Error> {
173        let log_dir = Self::get_log_dir()?;
174        let mut log_files: Vec<_> = fs::read_dir(&log_dir)?
175            .filter_map(|e| e.ok())
176            .filter(|e| e.path().extension().map(|ext| ext == "log").unwrap_or(false))
177            .collect();
178
179        // Sort by modification time (oldest first)
180        log_files.sort_by_key(|e| {
181            e.metadata().and_then(|m| m.modified()).unwrap_or(SystemTime::UNIX_EPOCH)
182        });
183
184        // Remove oldest files beyond keep_count
185        let total_sessions = log_files.len();
186        if total_sessions > keep_count {
187            for entry in log_files.iter().take(total_sessions - keep_count) {
188                let _ = fs::remove_file(entry.path());
189            }
190        }
191
192        Ok(())
193    }
194
195    fn timestamp() -> String {
196        let now = SystemTime::now()
197            .duration_since(UNIX_EPOCH)
198            .unwrap_or_default()
199            .as_secs();
200        let secs = now % 60;
201        let mins = (now / 60) % 60;
202        let hours = (now / 3600) % 24;
203        format!("{:02}:{:02}:{:02}", hours, mins, secs)
204    }
205
206    /// Log an API call
207    pub fn api_call(&self, model: &str, input_tokens: u32, cached: bool) {
208        if !self.is_enabled() { return; }
209        let count = API_CALL_COUNT.fetch_add(1, Ordering::Relaxed) + 1;
210        let msg = format!(
211            "API#{}: model={}, input_tokens={}, cached={}",
212            count,
213            model,
214            input_tokens,
215            cached
216        );
217        self.write_log("API", &msg);
218    }
219
220    /// Log compression trigger
221    pub fn compression(&self, original_tokens: u32, compressed_tokens: u32, ratio: f32) {
222        if !self.is_enabled() { return; }
223        let count = COMPRESSION_COUNT.fetch_add(1, Ordering::Relaxed) + 1;
224        let saved = original_tokens - compressed_tokens;
225        let msg = format!(
226            "COMPRESSION#{}: original={}, compressed={}, saved={}, ratio={:.1}%",
227            count,
228            original_tokens,
229            compressed_tokens,
230            saved,
231            ratio * 100.0
232        );
233        self.write_log("COMPRESS", &msg);
234    }
235
236    /// Log memory save
237    pub fn memory_save(&self, entries: usize, summary_len: usize) {
238        if !self.is_enabled() { return; }
239        let count = MEMORY_SAVE_COUNT.fetch_add(1, Ordering::Relaxed) + 1;
240        let msg = format!(
241            "MEMORY#{}: entries={}, summary_len={}chars",
242            count,
243            entries,
244            summary_len
245        );
246        self.write_log("MEMORY", &msg);
247    }
248
249    /// Log keyword extraction
250    pub fn keywords_extracted(&self, keywords: &[String], source: &str) {
251        if !self.is_enabled() { return; }
252        let msg = format!(
253            "{} extracted from {}chars | keywords: {}",
254            keywords.len(),
255            source.len(),
256            keywords.join(", ")
257        );
258        self.write_log("KEYWORDS", &msg);
259    }
260
261    /// Log tool execution
262    pub fn tool_call(&self, tool: &str, input_preview: &str, result_preview: &str) {
263        if !self.is_enabled() { return; }
264        let count = TOOL_CALL_COUNT.fetch_add(1, Ordering::Relaxed) + 1;
265        let msg = format!(
266            "TOOL#{}: {} | input: {} | result: {}",
267            count,
268            tool,
269            truncate(input_preview, 50),
270            truncate(result_preview, 50)
271        );
272        self.write_log("TOOL", &msg);
273    }
274
275    /// Log session save
276    pub fn session_save(&self, message_count: usize, total_tokens: u64) {
277        if !self.is_enabled() { return; }
278        let msg = format!(
279            "SESSION: messages={}, total_tokens={}",
280            message_count,
281            total_tokens
282        );
283        self.write_log("SESSION", &msg);
284    }
285
286    /// Log generic debug message
287    pub fn log(&self, category: &str, message: &str) {
288        if !self.is_enabled() { return; }
289        self.write_log(category, message);
290    }
291
292    /// Log API request body (for debug)
293    pub fn api_request(&self, url: &str, body: &str) {
294        if !self.is_enabled() { return; }
295        // Write full content to file
296        let body_preview = if body.len() > 5000 {
297            truncate_with_suffix(body, 5000)
298        } else {
299            body.to_string()
300        };
301        let msg = format!(
302            "API_REQUEST: url={}\n---REQUEST_BODY---\n{}\n---END---",
303            url,
304            body_preview
305        );
306        self.write(&format!("[{}] {}", Self::timestamp(), msg));
307
308        // Send brief summary to debug panel
309        let panel_msg = format!("url={} | body_len={}chars", url, body.len());
310        self.send_debug_event("API_REQUEST", &panel_msg);
311    }
312
313    /// Log API response (for debug)
314    pub fn api_response(&self, status: u16, body: &str) {
315        if !self.is_enabled() { return; }
316        // Write full content to file
317        let body_preview = if body.len() > 10000 {
318            truncate_with_suffix(body, 10000)
319        } else {
320            body.to_string()
321        };
322        let msg = format!(
323            "API_RESPONSE: status={}\n---RESPONSE_BODY---\n{}\n---END---",
324            status,
325            body_preview
326        );
327        self.write(&format!("[{}] {}", Self::timestamp(), msg));
328
329        // Send brief summary to debug panel
330        let panel_msg = format!("status={} | body_len={}chars", status, body.len());
331        self.send_debug_event("API_RESPONSE", &panel_msg);
332    }
333
334    /// Log streaming chunk (for debug, limited)
335    pub fn stream_chunk(&self, chunk_type: &str, content: &str) {
336        if !self.is_enabled() { return; }
337        // Only log small chunks to avoid flooding
338        let preview = if content.len() > 200 {
339            truncate_with_suffix(content, 200)
340        } else {
341            content.to_string()
342        };
343        let msg = format!(
344            "[{}] STREAM_CHUNK: type={} | {}",
345            Self::timestamp(),
346            chunk_type,
347            preview
348        );
349        self.write(&msg);
350    }
351
352    /// Log AI memory extraction (keyword extraction with fast model)
353    pub fn memory_ai_keywords(&self, model: &str, keywords_count: usize, source_len: usize, used_ai: bool) {
354        if !self.is_enabled() { return; }
355        let method = if used_ai { "AI" } else { "rule" };
356        let msg = format!(
357            "MEMORY_AI_KEYWORDS: model={}, method={}, keywords={}, source_len={}chars",
358            model,
359            method,
360            keywords_count,
361            source_len
362        );
363        self.write_log("MEMORY", &msg);
364    }
365
366    /// Log AI memory detection (memory extraction from response)
367    pub fn memory_ai_detection(&self, model: &str, entries_count: usize, text_len: usize, used_ai: bool) {
368        if !self.is_enabled() { return; }
369        let method = if used_ai { "AI" } else { "rule" };
370        let msg = format!(
371            "MEMORY_AI_DETECT: model={}, method={}, entries={}, text_len={}chars",
372            model,
373            method,
374            entries_count,
375            text_len
376        );
377        self.write_log("MEMORY", &msg);
378    }
379
380    fn write(&self, msg: &str) {
381        // Check if debug mode is enabled
382        if !self.is_enabled() {
383            return;
384        }
385
386        // Write to file only, don't print to console (would mess up TUI)
387        if let Ok(mut guard) = self.file.lock() {
388            if let Some(ref mut file) = *guard {
389                let _ = file.write_all(msg.as_bytes());
390                let _ = file.write_all(b"\n");
391                let _ = file.flush();
392            }
393        }
394
395        // Check for rotation after write
396        self.rotate_if_needed();
397    }
398
399    /// Write log with category and send event to TUI debug panel
400    fn write_log(&self, category: &str, message: &str) {
401        if !self.is_enabled() { return; }
402
403        let msg = format!("[{}] {}: {}", Self::timestamp(), category, message);
404        self.write(&msg);
405
406        // Send event to TUI debug panel
407        self.send_debug_event(category, message);
408    }
409
410    /// Send debug event to TUI panel only (no file write)
411    fn send_debug_event(&self, category: &str, message: &str) {
412        if let Ok(guard) = DEBUG_EVENT_SENDER.lock()
413            && let Some(ref sender) = *guard
414        {
415            let _ = sender.try_send(AgentEvent::debug_log(category, message));
416        }
417    }
418
419    /// Get statistics
420    pub fn stats(&self) -> DebugStats {
421        DebugStats {
422            api_calls: API_CALL_COUNT.load(Ordering::Relaxed),
423            compressions: COMPRESSION_COUNT.load(Ordering::Relaxed),
424            memory_saves: MEMORY_SAVE_COUNT.load(Ordering::Relaxed),
425            tool_calls: TOOL_CALL_COUNT.load(Ordering::Relaxed),
426        }
427    }
428}
429
430fn truncate(s: &str, max: usize) -> String {
431    truncate_with_suffix(s, max)
432}
433
434/// Debug statistics
435#[derive(Debug, Clone)]
436pub struct DebugStats {
437    pub api_calls: u64,
438    pub compressions: u64,
439    pub memory_saves: u64,
440    pub tool_calls: u64,
441}
442
443impl DebugStats {
444    pub fn format(&self) -> String {
445        format!(
446            "API: {} │ Compress: {} │ Memory: {} │ Tools: {}",
447            self.api_calls, self.compressions, self.memory_saves, self.tool_calls
448        )
449    }
450}
451
452/// Global debug logger (lazy initialized)
453static DEBUG_LOG: once_cell::sync::Lazy<DebugLog> = once_cell::sync::Lazy::new(|| {
454    // Try to load .env file first (from current directory)
455    let _ = dotenvy::dotenv();
456
457    // Also try project-level .matrix/.env
458    if let Ok(cwd) = std::env::current_dir() {
459        let matrix_env = cwd.join(MATRIX_DIR).join(".env");
460        if matrix_env.exists() {
461            let _ = dotenvy::from_path(&matrix_env);
462        }
463    }
464
465    DebugLog::new()
466});
467
468/// Global event sender for TUI debug panel
469static DEBUG_EVENT_SENDER: once_cell::sync::Lazy<Mutex<Option<mpsc::Sender<AgentEvent>>>> =
470    once_cell::sync::Lazy::new(|| Mutex::new(None));
471
472/// Get the global debug logger
473pub fn debug_log() -> &'static DebugLog {
474    &DEBUG_LOG
475}
476
477/// Enable debug logging with optional session ID
478pub fn enable_debug_logging(session_id: Option<&str>) {
479    DEBUG_LOG.enable(session_id);
480}
481
482/// Disable debug logging
483pub fn disable_debug_logging() {
484    DEBUG_LOG.disable();
485}
486
487/// Check if debug logging is enabled
488pub fn is_debug_enabled() -> bool {
489    DEBUG_LOG.is_enabled()
490}
491
492/// Set event sender for TUI debug panel
493/// This allows debug logs to be displayed in the TUI debug panel
494pub fn set_debug_event_sender(sender: mpsc::Sender<AgentEvent>) {
495    if let Ok(mut guard) = DEBUG_EVENT_SENDER.lock() {
496        *guard = Some(sender);
497    }
498}
499
500/// Convenience macros
501#[macro_export]
502macro_rules! debug_api {
503    ($model:expr, $tokens:expr, $cached:expr) => {
504        $crate::debug::debug_log().api_call($model, $tokens, $cached)
505    };
506}
507
508#[macro_export]
509macro_rules! debug_compress {
510    ($orig:expr, $comp:expr, $ratio:expr) => {
511        $crate::debug::debug_log().compression($orig, $comp, $ratio)
512    };
513}
514
515#[macro_export]
516macro_rules! debug_memory {
517    ($entries:expr, $len:expr) => {
518        $crate::debug::debug_log().memory_save($entries, $len)
519    };
520}
521
522#[macro_export]
523macro_rules! debug_keywords {
524    ($keywords:expr, $source:expr) => {
525        $crate::debug::debug_log().keywords_extracted($keywords, $source)
526    };
527}
528
529#[macro_export]
530macro_rules! debug_tool {
531    ($tool:expr, $input:expr, $result:expr) => {
532        $crate::debug::debug_log().tool_call($tool, $input, $result)
533    };
534}
535
536#[macro_export]
537macro_rules! debug_session {
538    ($msgs:expr, $tokens:expr) => {
539        $crate::debug::debug_log().session_save($msgs, $tokens)
540    };
541}
542
543#[macro_export]
544macro_rules! debug_log_msg {
545    ($cat:expr, $msg:expr) => {
546        $crate::debug::debug_log().log($cat, $msg)
547    };
548}
549
550#[macro_export]
551macro_rules! debug_api_request {
552    ($url:expr, $body:expr) => {
553        $crate::debug::debug_log().api_request($url, $body)
554    };
555}
556
557#[macro_export]
558macro_rules! debug_api_response {
559    ($status:expr, $body:expr) => {
560        $crate::debug::debug_log().api_response($status, $body)
561    };
562}
563
564#[macro_export]
565macro_rules! debug_stream_chunk {
566    ($type:expr, $content:expr) => {
567        $crate::debug::debug_log().stream_chunk($type, $content)
568    };
569}
570
571#[macro_export]
572macro_rules! debug_memory_ai_keywords {
573    ($model:expr, $count:expr, $len:expr, $ai:expr) => {
574        $crate::debug::debug_log().memory_ai_keywords($model, $count, $len, $ai)
575    };
576}
577
578#[macro_export]
579macro_rules! debug_memory_ai_detect {
580    ($model:expr, $count:expr, $len:expr, $ai:expr) => {
581        $crate::debug::debug_log().memory_ai_detection($model, $count, $len, $ai)
582    };
583}
matrixcode_core/debug.rs

matrixcode_core/
debug.rs
