fraiseql_core/runtime/
sql_logger.rs

1//! Structured SQL query logging and tracing.
2//!
3//! Provides comprehensive SQL query logging with:
4//! - Query parameters (sanitized for security)
5//! - Execution timing
6//! - Result metrics (rows affected)
7//! - Error tracking
8//! - Performance statistics
9
10use std::time::Instant;
11
12use serde::{Deserialize, Serialize};
13use tracing::{Level, debug, span, warn};
14
15/// SQL query log entry with execution details.
16#[derive(Debug, Clone, Serialize, Deserialize)]
17pub struct SqlQueryLog {
18    /// Query ID for correlation
19    pub query_id: String,
20
21    /// SQL statement (truncated for very large queries)
22    pub sql: String,
23
24    /// Bound parameters count
25    pub param_count: usize,
26
27    /// Execution time in microseconds
28    pub duration_us: u64,
29
30    /// Number of rows affected/returned
31    pub rows_affected: Option<usize>,
32
33    /// Whether query executed successfully
34    pub success: bool,
35
36    /// Error message if query failed
37    pub error: Option<String>,
38
39    /// Database operation type (SELECT, INSERT, UPDATE, DELETE, etc.)
40    pub operation: SqlOperation,
41
42    /// Optional slow query warning threshold (microseconds)
43    pub slow_threshold_us: Option<u64>,
44
45    /// Whether this query exceeded slow threshold
46    pub was_slow: bool,
47}
48
49/// SQL operation type for classification.
50#[derive(Debug, Clone, Copy, PartialEq, Eq, Serialize, Deserialize)]
51#[non_exhaustive]
52pub enum SqlOperation {
53    /// SELECT query
54    Select,
55    /// INSERT query
56    Insert,
57    /// UPDATE query
58    Update,
59    /// DELETE query
60    Delete,
61    /// Other operation (DDL, administrative)
62    Other,
63}
64
65impl SqlOperation {
66    /// Detect operation type from SQL string.
67    pub fn from_sql(sql: &str) -> Self {
68        let trimmed = sql.trim_start().to_uppercase();
69
70        if trimmed.starts_with("SELECT") {
71            SqlOperation::Select
72        } else if trimmed.starts_with("INSERT") {
73            SqlOperation::Insert
74        } else if trimmed.starts_with("UPDATE") {
75            SqlOperation::Update
76        } else if trimmed.starts_with("DELETE") {
77            SqlOperation::Delete
78        } else {
79            SqlOperation::Other
80        }
81    }
82}
83
84impl std::fmt::Display for SqlOperation {
85    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
86        match self {
87            SqlOperation::Select => write!(f, "SELECT"),
88            SqlOperation::Insert => write!(f, "INSERT"),
89            SqlOperation::Update => write!(f, "UPDATE"),
90            SqlOperation::Delete => write!(f, "DELETE"),
91            SqlOperation::Other => write!(f, "OTHER"),
92        }
93    }
94}
95
96/// Builder for creating SQL query logs.
97#[must_use = "call .finish_success() or .finish_error() to construct the final value"]
98pub struct SqlQueryLogBuilder {
99    query_id:          String,
100    sql:               String,
101    param_count:       usize,
102    start:             Instant,
103    slow_threshold_us: Option<u64>,
104}
105
106impl SqlQueryLogBuilder {
107    /// Create new SQL query log builder.
108    ///
109    /// # Arguments
110    /// * `query_id` - Unique identifier for the GraphQL query
111    /// * `sql` - The SQL statement (will be truncated if > 2000 chars)
112    /// * `param_count` - Number of bound parameters
113    pub fn new(query_id: &str, sql: &str, param_count: usize) -> Self {
114        let truncated_sql = if sql.len() > 2000 {
115            format!("{}...", &sql[..2000])
116        } else {
117            sql.to_string()
118        };
119
120        Self {
121            query_id: query_id.to_string(),
122            sql: truncated_sql,
123            param_count,
124            start: Instant::now(),
125            slow_threshold_us: None,
126        }
127    }
128
129    /// Set slow query threshold in microseconds.
130    pub const fn with_slow_threshold(mut self, threshold_us: u64) -> Self {
131        self.slow_threshold_us = Some(threshold_us);
132        self
133    }
134
135    /// Finish logging and create log entry (successful execution).
136    pub fn finish_success(self, rows_affected: Option<usize>) -> SqlQueryLog {
137        let duration_us = u64::try_from(self.start.elapsed().as_micros()).unwrap_or(u64::MAX);
138        let was_slow = self.slow_threshold_us.is_some_and(|t| duration_us > t);
139
140        let log = SqlQueryLog {
141            query_id: self.query_id.clone(),
142            sql: self.sql.clone(),
143            param_count: self.param_count,
144            duration_us,
145            rows_affected,
146            success: true,
147            error: None,
148            operation: SqlOperation::from_sql(&self.sql),
149            slow_threshold_us: self.slow_threshold_us,
150            was_slow,
151        };
152
153        if was_slow {
154            warn!(
155                query_id = %log.query_id,
156                operation = %log.operation,
157                duration_us = log.duration_us,
158                threshold_us = self.slow_threshold_us.unwrap_or(0),
159                "Slow SQL query detected"
160            );
161        } else {
162            debug!(
163                query_id = %log.query_id,
164                operation = %log.operation,
165                duration_us = log.duration_us,
166                params = log.param_count,
167                "SQL query executed"
168            );
169        }
170
171        log
172    }
173
174    /// Finish logging and create log entry (failed execution).
175    pub fn finish_error(self, error: &str) -> SqlQueryLog {
176        let duration_us = u64::try_from(self.start.elapsed().as_micros()).unwrap_or(u64::MAX);
177
178        let log = SqlQueryLog {
179            query_id: self.query_id.clone(),
180            sql: self.sql.clone(),
181            param_count: self.param_count,
182            duration_us,
183            rows_affected: None,
184            success: false,
185            error: Some(error.to_string()),
186            operation: SqlOperation::from_sql(&self.sql),
187            slow_threshold_us: self.slow_threshold_us,
188            was_slow: false,
189        };
190
191        warn!(
192            query_id = %log.query_id,
193            operation = %log.operation,
194            duration_us = log.duration_us,
195            error = error,
196            "SQL query failed"
197        );
198
199        log
200    }
201}
202
203impl SqlQueryLog {
204    /// Get log entry as a formatted string suitable for logging.
205    pub fn to_log_string(&self) -> String {
206        if self.success {
207            format!(
208                "SQL {} query (query_id={}, duration_us={}, params={}, rows={:?})",
209                self.operation,
210                self.query_id,
211                self.duration_us,
212                self.param_count,
213                self.rows_affected
214            )
215        } else {
216            format!(
217                "SQL {} query FAILED (query_id={}, duration_us={}, error={})",
218                self.operation,
219                self.query_id,
220                self.duration_us,
221                self.error.as_ref().unwrap_or(&"Unknown".to_string())
222            )
223        }
224    }
225
226    /// Check if query was slow based on threshold.
227    pub const fn is_slow(&self) -> bool {
228        self.was_slow
229    }
230
231    /// Get execution time in milliseconds (for human-friendly display).
232    pub fn duration_ms(&self) -> f64 {
233        #[allow(clippy::cast_precision_loss)]
234        // Reason: duration_us is a microsecond counter used for display; f64 precision loss is
235        // acceptable
236        {
237            self.duration_us as f64 / 1000.0
238        }
239    }
240}
241
242/// Create a tracing span for SQL query execution.
243pub fn create_sql_span(query_id: &str, operation: SqlOperation) -> tracing::Span {
244    span!(
245        Level::DEBUG,
246        "sql_query",
247        query_id = query_id,
248        operation = %operation,
249    )
250}
251
252#[cfg(test)]
253mod tests {
254    use std::{thread, time::Duration};
255
256    use super::*;
257
258    #[test]
259    fn test_sql_operation_detection() {
260        assert_eq!(SqlOperation::from_sql("SELECT * FROM users"), SqlOperation::Select);
261        assert_eq!(SqlOperation::from_sql("  select id from users"), SqlOperation::Select);
262        assert_eq!(SqlOperation::from_sql("INSERT INTO users VALUES (1)"), SqlOperation::Insert);
263        assert_eq!(SqlOperation::from_sql("UPDATE users SET id=1"), SqlOperation::Update);
264        assert_eq!(SqlOperation::from_sql("DELETE FROM users"), SqlOperation::Delete);
265        assert_eq!(SqlOperation::from_sql("CREATE TABLE users (id INT)"), SqlOperation::Other);
266    }
267
268    #[test]
269    fn test_sql_operation_display() {
270        assert_eq!(SqlOperation::Select.to_string(), "SELECT");
271        assert_eq!(SqlOperation::Insert.to_string(), "INSERT");
272        assert_eq!(SqlOperation::Update.to_string(), "UPDATE");
273        assert_eq!(SqlOperation::Delete.to_string(), "DELETE");
274        assert_eq!(SqlOperation::Other.to_string(), "OTHER");
275    }
276
277    #[test]
278    fn test_builder_success() {
279        let builder = SqlQueryLogBuilder::new("query_1", "SELECT * FROM users", 0);
280        let log = builder.finish_success(Some(10));
281
282        assert!(log.success);
283        assert_eq!(log.query_id, "query_1");
284        assert_eq!(log.operation, SqlOperation::Select);
285        assert_eq!(log.rows_affected, Some(10));
286        assert!(log.error.is_none());
287        // duration_us is wall-clock time, may vary depending on system speed
288    }
289
290    #[test]
291    fn test_builder_error() {
292        let builder = SqlQueryLogBuilder::new("query_1", "SELECT * FROM nonexistent", 0);
293        let log = builder.finish_error("Table not found");
294
295        assert!(!log.success);
296        assert_eq!(log.error, Some("Table not found".to_string()));
297        assert!(log.rows_affected.is_none());
298    }
299
300    #[test]
301    fn test_query_truncation() {
302        let long_query = "a".repeat(3000);
303        let builder = SqlQueryLogBuilder::new("query_1", &long_query, 0);
304        let log = builder.finish_success(None);
305
306        assert!(log.sql.len() < 3000);
307        assert!(log.sql.ends_with("..."));
308    }
309
310    #[test]
311    fn test_slow_query_detection() {
312        let builder =
313            SqlQueryLogBuilder::new("query_1", "SELECT * FROM users", 0).with_slow_threshold(100);
314
315        let log = builder.finish_success(Some(5));
316
317        // Query should be considered fast (runs much faster than 100 us typically)
318        assert!(!log.was_slow);
319    }
320
321    #[test]
322    fn test_slow_query_warning() {
323        let builder =
324            SqlQueryLogBuilder::new("query_1", "SELECT * FROM users", 0).with_slow_threshold(1);
325
326        // Simulate slow query by sleeping
327        thread::sleep(Duration::from_micros(100));
328        let log = builder.finish_success(Some(5));
329
330        assert!(log.was_slow);
331    }
332
333    #[test]
334    fn test_log_string_success() {
335        let builder = SqlQueryLogBuilder::new("query_1", "SELECT * FROM users", 5);
336        let log = builder.finish_success(Some(10));
337
338        let log_str = log.to_log_string();
339        assert!(log_str.contains("SELECT"));
340        assert!(log_str.contains("query_1"));
341        assert!(log_str.contains("params=5"));
342        assert!(log_str.contains("rows=Some(10)"));
343    }
344
345    #[test]
346    fn test_log_string_error() {
347        let builder = SqlQueryLogBuilder::new("query_1", "SELECT * FROM users", 0);
348        let log = builder.finish_error("Connection timeout");
349
350        let log_str = log.to_log_string();
351        assert!(log_str.contains("FAILED"));
352        assert!(log_str.contains("Connection timeout"));
353    }
354
355    #[test]
356    fn test_duration_ms() {
357        let builder = SqlQueryLogBuilder::new("query_1", "SELECT * FROM users", 0);
358        thread::sleep(Duration::from_millis(10));
359        let log = builder.finish_success(None);
360
361        let ms = log.duration_ms();
362        assert!(ms >= 10.0);
363    }
364
365    #[test]
366    fn test_serialization() {
367        let builder = SqlQueryLogBuilder::new("query_1", "SELECT * FROM users", 3);
368        let log = builder.finish_success(Some(25));
369
370        let json = serde_json::to_string(&log).expect("serialize should work");
371        let restored: SqlQueryLog = serde_json::from_str(&json).expect("deserialize should work");
372
373        assert_eq!(restored.query_id, log.query_id);
374        assert_eq!(restored.operation, log.operation);
375        assert_eq!(restored.rows_affected, log.rows_affected);
376    }
377
378    #[test]
379    fn test_all_operations() {
380        let operations = vec![
381            SqlOperation::Select,
382            SqlOperation::Insert,
383            SqlOperation::Update,
384            SqlOperation::Delete,
385            SqlOperation::Other,
386        ];
387
388        for op in operations {
389            let builder = SqlQueryLogBuilder::new("query_1", "SELECT 1", 0);
390            let mut log = builder.finish_success(None);
391            log.operation = op;
392
393            assert_eq!(log.operation, op);
394            let log_str = log.to_log_string();
395            assert!(log_str.contains(&op.to_string()));
396        }
397    }
398
399    #[test]
400    fn test_param_count() {
401        let builder =
402            SqlQueryLogBuilder::new("query_1", "SELECT * FROM users WHERE id = ? AND name = ?", 2);
403        let log = builder.finish_success(Some(1));
404
405        assert_eq!(log.param_count, 2);
406        assert!(log.to_log_string().contains("params=2"));
407    }
408}
fraiseql_core/runtime/sql_logger.rs

fraiseql_core/runtime/
sql_logger.rs
