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

fraiseql_core/runtime/
sql_logger.rs
