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    /// Format an audit event for an explicitly configured sensitive sink.
16    ///
17    /// The conservative default remains value-free so adding the sensitive
18    /// sink does not force third-party formatters to disclose payloads or to
19    /// implement a new required trait method. Formatters that deliberately
20    /// support raw audit diagnostics must override this method.
21    fn format_sensitive_audit_log(&self, event: &RawAuditEvent) -> String {
22        self.format_audit_log(event)
23    }
24}
25
26/// A human-readable log formatter, designed for developers and operators.
27/// Formats time, elapsed duration, and entity changes cleanly.
28pub struct HumanReaderFormatter;
29
30impl HumanReaderFormatter {
31    fn format_trace_chain(&self, trace_chain: &[TraceNode]) -> String {
32        if !trace_chain.is_empty() {
33            trace_chain
34                .iter()
35                .enumerate()
36                .map(|(level, n)| format!("{}:{:?}:{}={}", level, n.kind, n.entity_type, n.comment))
37                .collect::<Vec<_>>()
38                .join(" -> ")
39        } else {
40            Default::default()
41        }
42    }
43
44    fn format_audit_log_internal(&self, event: &RawAuditEvent, include_values: bool) -> String {
45        let ts = chrono::Utc::now().format("%Y-%m-%d %H:%M:%S%.3f");
46        let trace_str = self.format_trace_chain(&event.trace_chain);
47        let trace_display = if !trace_str.is_empty() {
48            format!(" (Trace: {})", trace_str)
49        } else {
50            Default::default()
51        };
52
53        let field_changes = event
54            .changes
55            .iter()
56            .filter(|change| !change.field.starts_with('_'))
57            .map(|change| {
58                if include_values {
59                    let value = change
60                        .new_value
61                        .as_ref()
62                        .map(|value| format!("{:?}", value))
63                        .unwrap_or_else(|| "null".to_owned());
64                    format!("{}: {}", change.field, value)
65                } else {
66                    change.field.clone()
67                }
68            })
69            .collect::<Vec<_>>();
70        let fields_part = if field_changes.is_empty() {
71            String::new()
72        } else if include_values {
73            format!(" {{{}}}", field_changes.join(", "))
74        } else {
75            format!(" fields=[{}]", field_changes.join(", "))
76        };
77
78        format!(
79            "[{}]-[AUDIT]-Entity [{}:{}] {:?}{}{}",
80            ts,
81            event.entity,
82            audit_entity_id(event),
83            event.kind,
84            trace_display,
85            fields_part
86        )
87    }
88}
89
90impl LogFormatter for HumanReaderFormatter {
91    fn format_sql_log(&self, trace_chain: &[TraceNode], entry: &SqlLogEntry) -> String {
92        let ts = chrono::Utc::now().format("%Y-%m-%d %H:%M:%S%.3f");
93        let trace_str = self.format_trace_chain(trace_chain);
94        let trace_display = if !trace_str.is_empty() {
95            format!(" - [{}]", trace_str)
96        } else {
97            Default::default()
98        };
99
100        let elapsed_us = (entry.elapsed.as_secs_f64() * 1_000_000.0).round() as u64;
101        let intent = format!(
102            "comment={:?} purpose={:?} auditReason={:?}",
103            entry.comment, entry.purpose, entry.audit_reason
104        );
105        let mut output = format!(
106            "[{}]-[{:>5}µs]-[DEBUG]-SqlLogEntry{} - [{}] {}\n          Parameterized SQL: {}",
107            ts,
108            elapsed_us,
109            trace_display,
110            entry.result_summary,
111            intent,
112            entry.sql.replace('\n', " ")
113        );
114        if !entry.debug_sql.is_empty() {
115            output.push_str(&format!(
116                " params={:?}\n          Debug SQL: {}",
117                entry.params,
118                entry.debug_sql.replace('\n', " ")
119            ));
120        }
121        output
122    }
123
124    fn format_audit_log(&self, event: &RawAuditEvent) -> String {
125        self.format_audit_log_internal(event, false)
126    }
127
128    fn format_sensitive_audit_log(&self, event: &RawAuditEvent) -> String {
129        self.format_audit_log_internal(event, true)
130    }
131}
132
133/// A structured or debug formatter intended for machine consumption or fallback
134pub struct DebugReaderFormatter;
135
136impl DebugReaderFormatter {
137    fn format_trace_chain(&self, trace_chain: &[TraceNode]) -> String {
138        match trace_chain.is_empty() {
139            true => "(Trace: None)".to_string(),
140            false => format!(
141                "(Trace: {})",
142                trace_chain
143                    .iter()
144                    .enumerate()
145                    .map(|(level, n)| {
146                        format!("{}:{:?}:{}={}", level, n.kind, n.entity_type, n.comment)
147                    })
148                    .collect::<Vec<_>>()
149                    .join(" -> ")
150            ),
151        }
152    }
153}
154
155impl LogFormatter for DebugReaderFormatter {
156    fn format_sql_log(&self, trace_chain: &[TraceNode], entry: &SqlLogEntry) -> String {
157        let trace_str = self.format_trace_chain(trace_chain);
158        format!("[SQL_LOG] {} - Event: {:?}", trace_str, entry)
159    }
160
161    fn format_audit_log(&self, event: &RawAuditEvent) -> String {
162        let trace_str = self.format_trace_chain(&event.trace_chain);
163        let fields = event
164            .changes
165            .iter()
166            .filter(|change| !change.field.starts_with('_'))
167            .map(|change| change.field.as_str())
168            .collect::<Vec<_>>()
169            .join(",");
170        format!(
171            "[AUDIT_LOG] {} - entity={} id={} kind={:?} fields=[{}]",
172            trace_str,
173            event.entity,
174            audit_entity_id(event),
175            event.kind,
176            fields
177        )
178    }
179
180    fn format_sensitive_audit_log(&self, event: &RawAuditEvent) -> String {
181        let trace_str = self.format_trace_chain(&event.trace_chain);
182        format!("[AUDIT_LOG_RAW] {} - Event: {:?}", trace_str, event)
183    }
184}
185
186fn audit_entity_id(event: &RawAuditEvent) -> String {
187    event
188        .new_values
189        .as_ref()
190        .and_then(|values| values.get("id"))
191        .or_else(|| event.values.get("id"))
192        .map(|value| format!("{:?}", value))
193        .unwrap_or_else(|| "Unknown".to_owned())
194}
195
196/// Factory pattern for instantiating the correct log formatter
197pub struct LogFormatterFactory;
198
199impl LogFormatterFactory {
200    /// Returns a singleton reference to the configured LogFormatter.
201    /// It dynamically switches based on the TEAQL_LOG_FORMAT environment variable.
202    pub fn get_formatter() -> &'static (dyn LogFormatter + Send + Sync) {
203        static FORMATTER: std::sync::OnceLock<Box<dyn LogFormatter + Send + Sync>> =
204            std::sync::OnceLock::new();
205        FORMATTER
206            .get_or_init(|| {
207                let format =
208                    std::env::var("TEAQL_LOG_FORMAT").unwrap_or_else(|_| "human".to_string());
209                match format.as_str() {
210                    "json" | "debug" => Box::new(DebugReaderFormatter),
211                    _ => Box::new(HumanReaderFormatter),
212                }
213            })
214            .as_ref()
215    }
216}
217
218#[derive(Debug, Clone, Copy, PartialEq, Eq)]
219pub enum LogLevel {
220    Silent,
221    Summary,
222    Full,
223    FullWithPayload,
224}
225
226impl LogLevel {
227    pub fn parse(s: &str, default: LogLevel) -> Self {
228        match s {
229            "_silent" => LogLevel::Silent,
230            "_summary" => LogLevel::Summary,
231            "_full" => LogLevel::Full,
232            "_full_with_payload" => LogLevel::FullWithPayload,
233            _ => default,
234        }
235    }
236}
237
238pub struct LogConfig {
239    pub audit_level: LogLevel,
240    pub sql_level: LogLevel,
241    pub tool_level: LogLevel,
242    pub audit_entities: Option<Vec<String>>,
243    pub sql_tables: Option<Vec<String>>,
244    pub tool_focus: Option<Vec<String>>,
245}
246
247impl LogConfig {
248    pub fn load() -> Self {
249        let audit_level = LogLevel::parse(
250            &std::env::var("TEAQL_AUDIT_LOG").unwrap_or_default(),
251            LogLevel::Full,
252        );
253        let sql_level = LogLevel::parse(
254            &std::env::var("TEAQL_SQL_LOG").unwrap_or_default(),
255            LogLevel::Summary,
256        );
257        let tool_level = LogLevel::parse(
258            &std::env::var("TEAQL_TOOL_LOG").unwrap_or_default(),
259            LogLevel::Full,
260        );
261
262        let audit_entities = std::env::var("TEAQL_AUDIT_LOG_ENTITIES")
263            .ok()
264            .map(|s| s.split(',').map(|s| s.trim().to_string()).collect());
265        let sql_tables = std::env::var("TEAQL_SQL_LOG_TABLES")
266            .ok()
267            .map(|s| s.split(',').map(|s| s.trim().to_string()).collect());
268        let tool_focus = std::env::var("TEAQL_TOOL_LOG_FOCUS")
269            .ok()
270            .map(|s| s.split(',').map(|s| s.trim().to_string()).collect());
271
272        Self {
273            audit_level,
274            sql_level,
275            tool_level,
276            audit_entities,
277            sql_tables,
278            tool_focus,
279        }
280    }
281
282    pub fn should_log_audit(&self, entity: &str) -> bool {
283        if self.audit_level == LogLevel::Silent {
284            return false;
285        }
286        if let Some(entities) = &self.audit_entities
287            && !entities.iter().any(|e| e.eq_ignore_ascii_case(entity))
288        {
289            return false;
290        }
291        true
292    }
293
294    pub fn should_log_sensitive_audit(&self, entity: &str) -> bool {
295        self.audit_level == LogLevel::FullWithPayload && self.should_log_audit(entity)
296    }
297
298    pub fn should_log_sql(&self, sql: &str) -> bool {
299        if self.sql_level == LogLevel::Silent {
300            return false;
301        }
302        if let Some(tables) = &self.sql_tables {
303            let sql_lower = sql.to_ascii_lowercase();
304            if !tables
305                .iter()
306                .any(|t| sql_lower.contains(&t.to_ascii_lowercase()))
307            {
308                return false;
309            }
310        }
311        true
312    }
313
314    pub fn should_log_tool(&self, module: &str) -> bool {
315        if self.tool_level == LogLevel::Silent {
316            return false;
317        }
318        if let Some(focus) = &self.tool_focus
319            && !focus.iter().any(|f| f.eq_ignore_ascii_case(module))
320        {
321            return false;
322        }
323        true
324    }
325}
326
327/// Manager that handles reading the endpoint environment variable and dispatching to the factory
328pub struct LogManager;
329
330static LOG_ENDPOINT: std::sync::OnceLock<Option<String>> = std::sync::OnceLock::new();
331static SQL_DEBUG_ENDPOINT: std::sync::OnceLock<Option<String>> = std::sync::OnceLock::new();
332static AUDIT_DEBUG_ENDPOINT: std::sync::OnceLock<Option<String>> = std::sync::OnceLock::new();
333static HEADER_WRITTEN: std::sync::Once = std::sync::Once::new();
334
335const EXTREME_TEST_FLAG: &str =
336    "__i_agree_to_disable_runtime_trace_only_for_extreme_performance_testing";
337
338impl LogManager {
339    pub fn config() -> &'static LogConfig {
340        static CONFIG: std::sync::OnceLock<LogConfig> = std::sync::OnceLock::new();
341        CONFIG.get_or_init(LogConfig::load)
342    }
343
344    fn get_log_endpoint() -> Option<&'static str> {
345        LOG_ENDPOINT
346            .get_or_init(|| {
347                let mode = std::env::var("TEAQL_TRACE_MODE").unwrap_or_default();
348                if mode == "off" {
349                    let ack = std::env::var("TEAQL_TRACE_OFF_ACK").unwrap_or_default();
350                    if ack == EXTREME_TEST_FLAG {
351                        return Some("off".to_string());
352                    }
353                    // If they didn't sign the waiver, ignore the off request and fallthrough
354                }
355
356                std::env::var("TEAQL_LOG_ENDPOINT")
357                    .ok()
358                    .filter(|v| !v.is_empty())
359                    .or_else(|| {
360                        if let Ok(val) = std::env::var("TEAQL_DOMAIN")
361                            && !val.is_empty()
362                        {
363                            return Some(format!("{}.log", val));
364                        }
365                        let exe_name = std::env::current_exe()
366                            .ok()
367                            .and_then(|p| p.file_name().map(|s| s.to_string_lossy().into_owned()))
368                            .unwrap_or_else(|| "teaql".to_string());
369                        Some(format!("{}.log", exe_name))
370                    })
371            })
372            .as_deref()
373    }
374
375    fn get_sql_debug_endpoint() -> Option<&'static str> {
376        SQL_DEBUG_ENDPOINT
377            .get_or_init(|| {
378                std::env::var("TEAQL_SQL_DEBUG_ENDPOINT")
379                    .ok()
380                    .filter(|endpoint| !endpoint.trim().is_empty())
381            })
382            .as_deref()
383    }
384
385    fn get_audit_debug_endpoint() -> Option<&'static str> {
386        AUDIT_DEBUG_ENDPOINT
387            .get_or_init(|| {
388                std::env::var("TEAQL_AUDIT_DEBUG_ENDPOINT")
389                    .ok()
390                    .filter(|endpoint| !endpoint.trim().is_empty())
391            })
392            .as_deref()
393    }
394
395    fn write_header_if_needed(endpoint: &str) {
396        if endpoint == "off" {
397            return;
398        }
399        HEADER_WRITTEN.call_once(|| {
400            let header = include_str!("log_header.txt");
401            match endpoint {
402                "stdout" => println!("{}", header),
403                path => {
404                    if let Ok(mut file) = std::fs::OpenOptions::new()
405                        .create(true)
406                        .append(true)
407                        .open(path)
408                    {
409                        use std::io::Write;
410                        let _ = writeln!(file, "{}", header);
411                    }
412                }
413            }
414        });
415    }
416
417    fn write_to_file(content: &str) {
418        if let Some(endpoint) = Self::get_log_endpoint() {
419            if endpoint == "off" {
420                return;
421            }
422
423            Self::write_header_if_needed(endpoint);
424
425            match endpoint {
426                "stdout" => println!("{}", content),
427                path => {
428                    if let Ok(mut file) = std::fs::OpenOptions::new()
429                        .create(true)
430                        .append(true)
431                        .open(path)
432                    {
433                        use std::io::Write;
434                        let _ = writeln!(file, "{}", content);
435                    }
436                }
437            }
438        }
439    }
440
441    pub fn write_sql_log(trace_chain: &[TraceNode], entry: &SqlLogEntry) {
442        if !Self::config().should_log_sql(&entry.sql) {
443            return;
444        }
445        if let Some(endpoint) = Self::get_log_endpoint() {
446            if endpoint == "off" {
447                return;
448            }
449            let content = LogFormatterFactory::get_formatter().format_sql_log(trace_chain, entry);
450            Self::write_to_file(&content);
451        }
452    }
453
454    pub(crate) fn write_sensitive_sql_log(trace_chain: &[TraceNode], entry: &SqlLogEntry) {
455        if !Self::config().should_log_sql(&entry.sql)
456            || matches!(Self::get_log_endpoint(), Some("off"))
457        {
458            return;
459        }
460        let Some(endpoint) = Self::get_sql_debug_endpoint() else {
461            return;
462        };
463        let content = LogFormatterFactory::get_formatter().format_sql_log(trace_chain, entry);
464        // If a diagnostic statement exceeds the bound, its partial rendering
465        // must be visibly non-executable rather than appearing copy-pasteable.
466        let content = truncate_sensitive_sql_log(&content, 64 * 1024);
467        match endpoint {
468            "stdout" => println!("{content}"),
469            path => {
470                if let Ok(mut file) = std::fs::OpenOptions::new()
471                    .create(true)
472                    .append(true)
473                    .open(path)
474                {
475                    use std::io::Write;
476                    let _ = writeln!(file, "{content}");
477                }
478            }
479        }
480    }
481
482    pub fn write_audit_log(event: &RawAuditEvent) {
483        if !Self::config().should_log_audit(&event.entity) {
484            return;
485        }
486        if let Some(endpoint) = Self::get_log_endpoint() {
487            if endpoint == "off" {
488                return;
489            }
490            let content = LogFormatterFactory::get_formatter().format_audit_log(event);
491            Self::write_to_file(&content);
492        }
493        if !Self::config().should_log_sensitive_audit(&event.entity) {
494            return;
495        }
496        let Some(endpoint) = Self::get_audit_debug_endpoint() else {
497            return;
498        };
499        let content = LogFormatterFactory::get_formatter().format_sensitive_audit_log(event);
500        let content = truncate_sensitive_audit_log(&content, 64 * 1024);
501        match endpoint {
502            "stdout" => println!("{content}"),
503            path => {
504                if let Ok(mut file) = std::fs::OpenOptions::new()
505                    .create(true)
506                    .append(true)
507                    .open(path)
508                {
509                    use std::io::Write;
510                    let _ = writeln!(file, "{content}");
511                }
512            }
513        }
514    }
515}
516
517fn truncate_sensitive_sql_log(content: &str, max_bytes: usize) -> String {
518    if content.len() <= max_bytes {
519        return content.to_owned();
520    }
521    let mut end = max_bytes;
522    while !content.is_char_boundary(end) {
523        end -= 1;
524    }
525    format!(
526        "{}\n[TRUNCATED; NOT EXECUTABLE: diagnostic SQL exceeded {} bytes]",
527        &content[..end],
528        max_bytes
529    )
530}
531
532fn truncate_sensitive_audit_log(content: &str, max_bytes: usize) -> String {
533    if content.len() <= max_bytes {
534        return content.to_owned();
535    }
536    let mut end = max_bytes;
537    while !content.is_char_boundary(end) {
538        end -= 1;
539    }
540    format!(
541        "{}\n[TRUNCATED: sensitive audit event exceeded {} bytes]",
542        &content[..end],
543        max_bytes
544    )
545}
546
547#[cfg(test)]
548mod diagnostic_log_tests {
549    use super::{
550        DebugReaderFormatter, HumanReaderFormatter, LogConfig, LogFormatter, LogLevel,
551        truncate_sensitive_audit_log, truncate_sensitive_sql_log,
552    };
553    use crate::RawAuditEvent;
554    use teaql_core::{Record, Value};
555
556    #[test]
557    fn bounded_diagnostic_log_marks_partial_sql_non_executable() {
558        assert_eq!(truncate_sensitive_sql_log("SELECT 1", 100), "SELECT 1");
559        let truncated = truncate_sensitive_sql_log("SELECT '🔐private-value'", 11);
560        assert!(truncated.contains("TRUNCATED; NOT EXECUTABLE"));
561        assert!(!truncated.contains("private-value"));
562    }
563
564    #[test]
565    fn ordinary_audit_formatters_disclose_field_names_but_not_values() {
566        let event = RawAuditEvent::created(
567            "School",
568            Record::from([
569                ("id".to_owned(), Value::U64(7)),
570                (
571                    "name".to_owned(),
572                    Value::Text("private-school-name".to_owned()),
573                ),
574            ]),
575        );
576
577        for formatter in [
578            &HumanReaderFormatter as &dyn LogFormatter,
579            &DebugReaderFormatter as &dyn LogFormatter,
580        ] {
581            let safe = formatter.format_audit_log(&event);
582            assert!(safe.contains("School"));
583            assert!(safe.contains("name"));
584            assert!(!safe.contains("private-school-name"));
585
586            let sensitive = formatter.format_sensitive_audit_log(&event);
587            assert!(sensitive.contains("private-school-name"));
588        }
589    }
590
591    #[test]
592    fn bounded_sensitive_audit_log_does_not_split_utf8() {
593        let truncated = truncate_sensitive_audit_log("audit 🔐private-value", 10);
594        assert!(truncated.contains("TRUNCATED"));
595        assert!(!truncated.contains("private-value"));
596    }
597
598    #[test]
599    fn raw_audit_output_requires_full_with_payload_level() {
600        let config = |audit_level| LogConfig {
601            audit_level,
602            sql_level: LogLevel::Silent,
603            tool_level: LogLevel::Silent,
604            audit_entities: None,
605            sql_tables: None,
606            tool_focus: None,
607        };
608
609        assert!(!config(LogLevel::Summary).should_log_sensitive_audit("School"));
610        assert!(!config(LogLevel::Full).should_log_sensitive_audit("School"));
611        assert!(config(LogLevel::FullWithPayload).should_log_sensitive_audit("School"));
612    }
613}
teaql_runtime/log_formatter.rs

teaql_runtime/
log_formatter.rs
