teaql_runtime/
log_formatter.rs

1use crate::event::RawAuditEvent;
2use teaql_core::TraceNode;
3
4/// Represents a log entry for SQL execution
5pub use crate::context::{SqlLogEntry, SqlLogOperation};
6
7/// A trait for defining how logs should be formatted before being output
8pub trait LogFormatter: Send + Sync {
9    /// Format an SQL log entry along with its trace chain
10    fn format_sql_log(&self, trace_chain: &[TraceNode], entry: &SqlLogEntry) -> String;
11
12    /// Format an audit or mutation event log
13    fn format_audit_log(&self, event: &RawAuditEvent) -> String;
14}
15
16/// A human-readable log formatter, designed for developers and operators.
17/// Formats time, elapsed duration, and entity changes cleanly.
18pub struct HumanReaderFormatter;
19
20impl HumanReaderFormatter {
21    fn format_trace_chain(&self, trace_chain: &[TraceNode]) -> String {
22        if !trace_chain.is_empty() {
23            trace_chain
24                .iter()
25                .enumerate()
26                .map(|(level, n)| format!("{}:{:?}:{}={}", level, n.kind, n.entity_type, n.comment))
27                .collect::<Vec<_>>()
28                .join(" -> ")
29        } else {
30            Default::default()
31        }
32    }
33}
34
35impl LogFormatter for HumanReaderFormatter {
36    fn format_sql_log(&self, trace_chain: &[TraceNode], entry: &SqlLogEntry) -> String {
37        let ts = chrono::Utc::now().format("%Y-%m-%d %H:%M:%S%.3f");
38        let trace_str = self.format_trace_chain(trace_chain);
39        let trace_display = if !trace_str.is_empty() {
40            format!(" - [{}]", trace_str)
41        } else {
42            Default::default()
43        };
44
45        let elapsed_us = (entry.elapsed.as_secs_f64() * 1_000_000.0).round() as u64;
46        let intent = format!(
47            "comment={:?} purpose={:?} auditReason={:?}",
48            entry.comment, entry.purpose, entry.audit_reason
49        );
50        let mut output = format!(
51            "[{}]-[{:>5}µs]-[DEBUG]-SqlLogEntry{} - [{}] {}\n          Parameterized SQL: {}",
52            ts,
53            elapsed_us,
54            trace_display,
55            entry.result_summary,
56            intent,
57            entry.sql.replace('\n', " ")
58        );
59        if !entry.debug_sql.is_empty() {
60            output.push_str(&format!(
61                " params={:?}\n          Debug SQL: {}",
62                entry.params,
63                entry.debug_sql.replace('\n', " ")
64            ));
65        }
66        output
67    }
68
69    fn format_audit_log(&self, event: &RawAuditEvent) -> String {
70        let ts = chrono::Utc::now().format("%Y-%m-%d %H:%M:%S%.3f");
71        let trace_str = self.format_trace_chain(&event.trace_chain);
72        let trace_display = if !trace_str.is_empty() {
73            format!(" (Trace: {})", trace_str)
74        } else {
75            Default::default()
76        };
77
78        let mut field_changes = Vec::new();
79        for change in &event.changes {
80            if change.field.starts_with('_') {
81                continue;
82            }
83            let val = change
84                .new_value
85                .as_ref()
86                .map(|v| format!("{:?}", v))
87                .unwrap_or_else(|| "null".to_string());
88            field_changes.push(format!("{}: {}", change.field, val));
89        }
90        let fields_part = if !field_changes.is_empty() {
91            format!(" {{{}}}", field_changes.join(", "))
92        } else {
93            Default::default()
94        };
95
96        let mut entity_id = "Unknown".to_string();
97        if let Some(vals) = &event.new_values
98            && let Some(id_val) = vals.get("id")
99        {
100            entity_id = format!("{:?}", id_val);
101        }
102
103        format!(
104            "[{}]-[AUDIT]-Entity [{}:{}] {:?}{}{}",
105            ts, event.entity, entity_id, event.kind, trace_display, fields_part
106        )
107    }
108}
109
110/// A structured or debug formatter intended for machine consumption or fallback
111pub struct DebugReaderFormatter;
112
113impl DebugReaderFormatter {
114    fn format_trace_chain(&self, trace_chain: &[TraceNode]) -> String {
115        match trace_chain.is_empty() {
116            true => "(Trace: None)".to_string(),
117            false => format!(
118                "(Trace: {})",
119                trace_chain
120                    .iter()
121                    .enumerate()
122                    .map(|(level, n)| {
123                        format!("{}:{:?}:{}={}", level, n.kind, n.entity_type, n.comment)
124                    })
125                    .collect::<Vec<_>>()
126                    .join(" -> ")
127            ),
128        }
129    }
130}
131
132impl LogFormatter for DebugReaderFormatter {
133    fn format_sql_log(&self, trace_chain: &[TraceNode], entry: &SqlLogEntry) -> String {
134        let trace_str = self.format_trace_chain(trace_chain);
135        format!("[SQL_LOG] {} - Event: {:?}", trace_str, entry)
136    }
137
138    fn format_audit_log(&self, event: &RawAuditEvent) -> String {
139        let trace_str = self.format_trace_chain(&event.trace_chain);
140        format!("[AUDIT_LOG] {} - Event: {:?}", trace_str, event)
141    }
142}
143
144/// Factory pattern for instantiating the correct log formatter
145pub struct LogFormatterFactory;
146
147impl LogFormatterFactory {
148    /// Returns a singleton reference to the configured LogFormatter.
149    /// It dynamically switches based on the TEAQL_LOG_FORMAT environment variable.
150    pub fn get_formatter() -> &'static (dyn LogFormatter + Send + Sync) {
151        static FORMATTER: std::sync::OnceLock<Box<dyn LogFormatter + Send + Sync>> =
152            std::sync::OnceLock::new();
153        FORMATTER
154            .get_or_init(|| {
155                let format =
156                    std::env::var("TEAQL_LOG_FORMAT").unwrap_or_else(|_| "human".to_string());
157                match format.as_str() {
158                    "json" | "debug" => Box::new(DebugReaderFormatter),
159                    _ => Box::new(HumanReaderFormatter),
160                }
161            })
162            .as_ref()
163    }
164}
165
166#[derive(Debug, Clone, Copy, PartialEq, Eq)]
167pub enum LogLevel {
168    Silent,
169    Summary,
170    Full,
171    FullWithPayload,
172}
173
174impl LogLevel {
175    pub fn parse(s: &str, default: LogLevel) -> Self {
176        match s {
177            "_silent" => LogLevel::Silent,
178            "_summary" => LogLevel::Summary,
179            "_full" => LogLevel::Full,
180            "_full_with_payload" => LogLevel::FullWithPayload,
181            _ => default,
182        }
183    }
184}
185
186pub struct LogConfig {
187    pub audit_level: LogLevel,
188    pub sql_level: LogLevel,
189    pub tool_level: LogLevel,
190    pub audit_entities: Option<Vec<String>>,
191    pub sql_tables: Option<Vec<String>>,
192    pub tool_focus: Option<Vec<String>>,
193}
194
195impl LogConfig {
196    pub fn load() -> Self {
197        let audit_level = LogLevel::parse(
198            &std::env::var("TEAQL_AUDIT_LOG").unwrap_or_default(),
199            LogLevel::Full,
200        );
201        let sql_level = LogLevel::parse(
202            &std::env::var("TEAQL_SQL_LOG").unwrap_or_default(),
203            LogLevel::Summary,
204        );
205        let tool_level = LogLevel::parse(
206            &std::env::var("TEAQL_TOOL_LOG").unwrap_or_default(),
207            LogLevel::Full,
208        );
209
210        let audit_entities = std::env::var("TEAQL_AUDIT_LOG_ENTITIES")
211            .ok()
212            .map(|s| s.split(',').map(|s| s.trim().to_string()).collect());
213        let sql_tables = std::env::var("TEAQL_SQL_LOG_TABLES")
214            .ok()
215            .map(|s| s.split(',').map(|s| s.trim().to_string()).collect());
216        let tool_focus = std::env::var("TEAQL_TOOL_LOG_FOCUS")
217            .ok()
218            .map(|s| s.split(',').map(|s| s.trim().to_string()).collect());
219
220        Self {
221            audit_level,
222            sql_level,
223            tool_level,
224            audit_entities,
225            sql_tables,
226            tool_focus,
227        }
228    }
229
230    pub fn should_log_audit(&self, entity: &str) -> bool {
231        if self.audit_level == LogLevel::Silent {
232            return false;
233        }
234        if let Some(entities) = &self.audit_entities
235            && !entities.iter().any(|e| e.eq_ignore_ascii_case(entity))
236        {
237            return false;
238        }
239        true
240    }
241
242    pub fn should_log_sql(&self, sql: &str) -> bool {
243        if self.sql_level == LogLevel::Silent {
244            return false;
245        }
246        if let Some(tables) = &self.sql_tables {
247            let sql_lower = sql.to_ascii_lowercase();
248            if !tables
249                .iter()
250                .any(|t| sql_lower.contains(&t.to_ascii_lowercase()))
251            {
252                return false;
253            }
254        }
255        true
256    }
257
258    pub fn should_log_tool(&self, module: &str) -> bool {
259        if self.tool_level == LogLevel::Silent {
260            return false;
261        }
262        if let Some(focus) = &self.tool_focus
263            && !focus.iter().any(|f| f.eq_ignore_ascii_case(module))
264        {
265            return false;
266        }
267        true
268    }
269}
270
271/// Manager that handles reading the endpoint environment variable and dispatching to the factory
272pub struct LogManager;
273
274static LOG_ENDPOINT: std::sync::OnceLock<Option<String>> = std::sync::OnceLock::new();
275static SQL_DEBUG_ENDPOINT: std::sync::OnceLock<Option<String>> = std::sync::OnceLock::new();
276static HEADER_WRITTEN: std::sync::Once = std::sync::Once::new();
277
278const EXTREME_TEST_FLAG: &str =
279    "__i_agree_to_disable_runtime_trace_only_for_extreme_performance_testing";
280
281impl LogManager {
282    pub fn config() -> &'static LogConfig {
283        static CONFIG: std::sync::OnceLock<LogConfig> = std::sync::OnceLock::new();
284        CONFIG.get_or_init(LogConfig::load)
285    }
286
287    fn get_log_endpoint() -> Option<&'static str> {
288        LOG_ENDPOINT
289            .get_or_init(|| {
290                let mode = std::env::var("TEAQL_TRACE_MODE").unwrap_or_default();
291                if mode == "off" {
292                    let ack = std::env::var("TEAQL_TRACE_OFF_ACK").unwrap_or_default();
293                    if ack == EXTREME_TEST_FLAG {
294                        return Some("off".to_string());
295                    }
296                    // If they didn't sign the waiver, ignore the off request and fallthrough
297                }
298
299                std::env::var("TEAQL_LOG_ENDPOINT")
300                    .ok()
301                    .filter(|v| !v.is_empty())
302                    .or_else(|| {
303                        if let Ok(val) = std::env::var("TEAQL_DOMAIN")
304                            && !val.is_empty()
305                        {
306                            return Some(format!("{}.log", val));
307                        }
308                        let exe_name = std::env::current_exe()
309                            .ok()
310                            .and_then(|p| p.file_name().map(|s| s.to_string_lossy().into_owned()))
311                            .unwrap_or_else(|| "teaql".to_string());
312                        Some(format!("{}.log", exe_name))
313                    })
314            })
315            .as_deref()
316    }
317
318    fn get_sql_debug_endpoint() -> Option<&'static str> {
319        SQL_DEBUG_ENDPOINT
320            .get_or_init(|| {
321                std::env::var("TEAQL_SQL_DEBUG_ENDPOINT")
322                    .ok()
323                    .filter(|endpoint| !endpoint.trim().is_empty())
324            })
325            .as_deref()
326    }
327
328    fn write_header_if_needed(endpoint: &str) {
329        if endpoint == "off" {
330            return;
331        }
332        HEADER_WRITTEN.call_once(|| {
333            let header = include_str!("log_header.txt");
334            match endpoint {
335                "stdout" => println!("{}", header),
336                path => {
337                    if let Ok(mut file) = std::fs::OpenOptions::new()
338                        .create(true)
339                        .append(true)
340                        .open(path)
341                    {
342                        use std::io::Write;
343                        let _ = writeln!(file, "{}", header);
344                    }
345                }
346            }
347        });
348    }
349
350    fn write_to_file(content: &str) {
351        if let Some(endpoint) = Self::get_log_endpoint() {
352            if endpoint == "off" {
353                return;
354            }
355
356            Self::write_header_if_needed(endpoint);
357
358            match endpoint {
359                "stdout" => println!("{}", content),
360                path => {
361                    if let Ok(mut file) = std::fs::OpenOptions::new()
362                        .create(true)
363                        .append(true)
364                        .open(path)
365                    {
366                        use std::io::Write;
367                        let _ = writeln!(file, "{}", content);
368                    }
369                }
370            }
371        }
372    }
373
374    pub fn write_sql_log(trace_chain: &[TraceNode], entry: &SqlLogEntry) {
375        if !Self::config().should_log_sql(&entry.sql) {
376            return;
377        }
378        if let Some(endpoint) = Self::get_log_endpoint() {
379            if endpoint == "off" {
380                return;
381            }
382            let content = LogFormatterFactory::get_formatter().format_sql_log(trace_chain, entry);
383            Self::write_to_file(&content);
384        }
385    }
386
387    pub(crate) fn write_sensitive_sql_log(trace_chain: &[TraceNode], entry: &SqlLogEntry) {
388        if !Self::config().should_log_sql(&entry.sql)
389            || matches!(Self::get_log_endpoint(), Some("off"))
390        {
391            return;
392        }
393        let Some(endpoint) = Self::get_sql_debug_endpoint() else {
394            return;
395        };
396        let content = LogFormatterFactory::get_formatter().format_sql_log(trace_chain, entry);
397        // If a diagnostic statement exceeds the bound, its partial rendering
398        // must be visibly non-executable rather than appearing copy-pasteable.
399        let content = truncate_sensitive_sql_log(&content, 64 * 1024);
400        match endpoint {
401            "stdout" => println!("{content}"),
402            path => {
403                if let Ok(mut file) = std::fs::OpenOptions::new()
404                    .create(true)
405                    .append(true)
406                    .open(path)
407                {
408                    use std::io::Write;
409                    let _ = writeln!(file, "{content}");
410                }
411            }
412        }
413    }
414
415    pub fn write_audit_log(event: &RawAuditEvent) {
416        if !Self::config().should_log_audit(&event.entity) {
417            return;
418        }
419        if let Some(endpoint) = Self::get_log_endpoint() {
420            if endpoint == "off" {
421                return;
422            }
423            let content = LogFormatterFactory::get_formatter().format_audit_log(event);
424            Self::write_to_file(&content);
425        }
426    }
427}
428
429fn truncate_sensitive_sql_log(content: &str, max_bytes: usize) -> String {
430    if content.len() <= max_bytes {
431        return content.to_owned();
432    }
433    let mut end = max_bytes;
434    while !content.is_char_boundary(end) {
435        end -= 1;
436    }
437    format!(
438        "{}\n[TRUNCATED; NOT EXECUTABLE: diagnostic SQL exceeded {} bytes]",
439        &content[..end],
440        max_bytes
441    )
442}
443
444#[cfg(test)]
445mod sensitive_sql_log_tests {
446    use super::truncate_sensitive_sql_log;
447
448    #[test]
449    fn bounded_diagnostic_log_marks_partial_sql_non_executable() {
450        assert_eq!(truncate_sensitive_sql_log("SELECT 1", 100), "SELECT 1");
451        let truncated = truncate_sensitive_sql_log("SELECT '🔐private-value'", 11);
452        assert!(truncated.contains("TRUNCATED; NOT EXECUTABLE"));
453        assert!(!truncated.contains("private-value"));
454    }
455}
teaql_runtime/log_formatter.rs

teaql_runtime/
log_formatter.rs
