toasty_core/driver/
log.rs

1//! Per-query tracing instrumentation shared by all drivers.
2//!
3//! Every driver emits one event per physical database operation through
4//! [`QueryLog`], so all backends produce the same shape: target
5//! `toasty::query` at `DEBUG` (escalated to `WARN` past the configured
6//! slow-statement threshold), with the statement text or operation name,
7//! elapsed time, row count, and outcome. Field names follow the
8//! [OpenTelemetry database semantic conventions] (the two-segment forms —
9//! `db.system`, `db.statement` — since `tracing` macros reject field names
10//! with more than two dot-separated segments).
11//!
12//! [OpenTelemetry database semantic conventions]: https://opentelemetry.io/docs/specs/semconv/database/
13
14use crate::driver::{ExecResponse, Rows};
15use crate::stmt::Value;
16
17use std::fmt::Write;
18use std::time::{Duration, Instant};
19
20/// The tracing target of the per-query event, shared by all drivers.
21pub const TARGET: &str = "toasty::query";
22
23/// Maximum number of parameter values rendered per statement.
24const MAX_PARAMS: usize = 32;
25
26/// Maximum number of characters rendered per string parameter.
27const MAX_STR_LEN: usize = 128;
28
29/// Maximum number of items rendered per list parameter.
30const MAX_LIST_ITEMS: usize = 8;
31
32/// Configuration for the per-query `toasty::query` tracing event.
33///
34/// Set on `Db::builder()` and handed to each driver connection at creation
35/// time through the [`ConnectContext`](super::ConnectContext) passed to
36/// [`Driver::connect`](super::Driver::connect).
37#[derive(Debug, Clone, Copy)]
38pub struct QueryLogConfig {
39    /// Include bound parameter values in the event. Off by default:
40    /// parameter values are application data and may contain secrets.
41    pub params: bool,
42
43    /// Emit the per-query event at `WARN` instead of `DEBUG` when
44    /// execution takes at least this long. `None` disables escalation.
45    pub slow_statement_threshold: Option<Duration>,
46}
47
48impl Default for QueryLogConfig {
49    fn default() -> Self {
50        Self {
51            params: false,
52            slow_statement_threshold: Some(Duration::from_secs(1)),
53        }
54    }
55}
56
57/// Measures one in-flight database operation and emits the `toasty::query`
58/// event when finished.
59///
60/// Construct with [`sql`](Self::sql) or [`operation`](Self::operation)
61/// immediately before executing, then call [`finish`](Self::finish) with the
62/// execution result. Timing runs from construction to `finish`.
63#[derive(Debug)]
64pub struct QueryLog<'a> {
65    config: QueryLogConfig,
66    system: &'static str,
67    query_text: Option<&'a str>,
68    operation: Option<&'a str>,
69    collection: Option<&'a str>,
70    params: Option<String>,
71    rows: Option<u64>,
72    start: Instant,
73}
74
75impl<'a> QueryLog<'a> {
76    /// Starts measuring a SQL statement execution.
77    pub fn sql<'v>(
78        config: &QueryLogConfig,
79        system: &'static str,
80        sql: &'a str,
81        params: impl IntoIterator<Item = &'v Value>,
82    ) -> Self {
83        Self {
84            config: *config,
85            system,
86            query_text: Some(sql),
87            operation: None,
88            collection: None,
89            params: render_params(config, params),
90            rows: None,
91            start: Instant::now(),
92        }
93    }
94
95    /// Starts measuring a key-value operation execution.
96    pub fn operation(
97        config: &QueryLogConfig,
98        system: &'static str,
99        operation: &'a str,
100        collection: Option<&'a str>,
101    ) -> Self {
102        Self {
103            config: *config,
104            system,
105            query_text: None,
106            operation: Some(operation),
107            collection,
108            params: None,
109            rows: None,
110            start: Instant::now(),
111        }
112    }
113
114    /// Records the number of rows returned, for drivers that know it before
115    /// handing back a stream. Row counts for count-style responses are read
116    /// from the [`ExecResponse`] in [`finish`](Self::finish) automatically.
117    pub fn rows(&mut self, rows: u64) {
118        self.rows = Some(rows);
119    }
120
121    /// Emits the `toasty::query` event describing `result`.
122    pub fn finish(self, result: &crate::Result<ExecResponse>) {
123        let elapsed = self.start.elapsed();
124        let duration_ms = elapsed.as_secs_f64() * 1e3;
125        let rows = self.rows.or(match result {
126            Ok(response) => match &response.values {
127                Rows::Count(count) => Some(*count),
128                _ => None,
129            },
130            Err(_) => None,
131        });
132        let slow = self
133            .config
134            .slow_statement_threshold
135            .is_some_and(|threshold| elapsed >= threshold);
136
137        let error = result.as_ref().err().map(tracing::field::display);
138        let message = match (slow, result) {
139            (_, Err(_)) => "query failed",
140            (true, Ok(_)) => "slow query",
141            (false, Ok(_)) => "query executed",
142        };
143
144        // Strings are recorded through `Display` so the default `fmt`
145        // subscriber prints them bare — SQL full of quoted identifiers is
146        // unreadable once escaped.
147        let system = tracing::field::display(self.system);
148        let statement = self.query_text.map(tracing::field::display);
149        let operation = self.operation.map(tracing::field::display);
150        let collection = self.collection.map(tracing::field::display);
151        let params = self.params.as_deref().map(tracing::field::display);
152
153        // `duration_ms` leads because the tracing macros mis-parse a dotted
154        // field name placed directly after `target:`.
155        if slow {
156            tracing::warn!(
157                target: "toasty::query",
158                duration_ms,
159                rows,
160                error,
161                db.system = system,
162                db.statement = statement,
163                db.operation = operation,
164                db.collection = collection,
165                db.params = params,
166                "{message}"
167            );
168        } else {
169            tracing::debug!(
170                target: "toasty::query",
171                duration_ms,
172                rows,
173                error,
174                db.system = system,
175                db.statement = statement,
176                db.operation = operation,
177                db.collection = collection,
178                db.params = params,
179                "{message}"
180            );
181        }
182    }
183}
184
185/// Renders parameter values to a bounded, human-readable list, or `None`
186/// when param logging is disabled or the event could not be observed anyway.
187/// Rendering happens before execution, when it is not yet known whether the
188/// event fires at `DEBUG` or (past the slow threshold) `WARN`, so both
189/// callsites are checked: a `RUST_LOG=warn` filter must still get params on
190/// slow-query events.
191fn render_params<'v>(
192    config: &QueryLogConfig,
193    params: impl IntoIterator<Item = &'v Value>,
194) -> Option<String> {
195    let enabled = tracing::event_enabled!(target: "toasty::query", tracing::Level::DEBUG)
196        || tracing::event_enabled!(target: "toasty::query", tracing::Level::WARN);
197    if !config.params || !enabled {
198        return None;
199    }
200
201    let mut out = String::from("[");
202    for (i, value) in params.into_iter().enumerate() {
203        if i > 0 {
204            out.push_str(", ");
205        }
206        if i == MAX_PARAMS {
207            out.push_str("...");
208            break;
209        }
210        render_value(&mut out, value);
211    }
212    out.push(']');
213    Some(out)
214}
215
216fn render_value(out: &mut String, value: &Value) {
217    let _ = match value {
218        Value::Null => {
219            out.push_str("NULL");
220            Ok(())
221        }
222        Value::Bool(v) => write!(out, "{v}"),
223        Value::I8(v) => write!(out, "{v}"),
224        Value::I16(v) => write!(out, "{v}"),
225        Value::I32(v) => write!(out, "{v}"),
226        Value::I64(v) => write!(out, "{v}"),
227        Value::U8(v) => write!(out, "{v}"),
228        Value::U16(v) => write!(out, "{v}"),
229        Value::U32(v) => write!(out, "{v}"),
230        Value::U64(v) => write!(out, "{v}"),
231        Value::F32(v) => write!(out, "{v}"),
232        Value::F64(v) => write!(out, "{v}"),
233        Value::Uuid(v) => write!(out, "{v}"),
234        Value::String(s) => {
235            render_str(out, s);
236            Ok(())
237        }
238        Value::Bytes(b) => write!(out, "<{} bytes>", b.len()),
239        Value::List(items) => {
240            out.push('[');
241            for (i, item) in items.iter().enumerate() {
242                if i > 0 {
243                    out.push_str(", ");
244                }
245                if i == MAX_LIST_ITEMS {
246                    out.push_str("...");
247                    break;
248                }
249                render_value(out, item);
250            }
251            out.push(']');
252            Ok(())
253        }
254        other => write!(out, "{other:?}"),
255    };
256}
257
258fn render_str(out: &mut String, s: &str) {
259    let total = s.chars().count();
260    if total <= MAX_STR_LEN {
261        let _ = write!(out, "{s:?}");
262    } else {
263        let prefix: String = s.chars().take(MAX_STR_LEN).collect();
264        let _ = write!(out, "{prefix:?}...({total} chars)");
265    }
266}
267
268#[cfg(test)]
269mod tests {
270    use super::*;
271
272    fn rendered(value: Value) -> String {
273        let mut out = String::new();
274        render_value(&mut out, &value);
275        out
276    }
277
278    #[test]
279    fn renders_scalars_bare() {
280        assert_eq!(rendered(Value::Null), "NULL");
281        assert_eq!(rendered(Value::Bool(true)), "true");
282        assert_eq!(rendered(Value::I64(-42)), "-42");
283        assert_eq!(rendered(Value::F64(1.5)), "1.5");
284    }
285
286    #[test]
287    fn renders_strings_quoted_and_truncated() {
288        assert_eq!(rendered(Value::String("hi".into())), "\"hi\"");
289
290        let long = "x".repeat(500);
291        let out = rendered(Value::String(long));
292        assert!(out.starts_with('"'));
293        assert!(out.ends_with("...(500 chars)"));
294        assert!(out.len() < 200);
295    }
296
297    #[test]
298    fn renders_bytes_as_length() {
299        assert_eq!(rendered(Value::Bytes(vec![0; 16])), "<16 bytes>");
300    }
301
302    #[test]
303    fn caps_list_items() {
304        let list = Value::List((0..20).map(Value::I64).collect());
305        assert_eq!(rendered(list), "[0, 1, 2, 3, 4, 5, 6, 7, ...]");
306    }
307}
toasty_core/driver/log.rs

toasty_core/driver/
log.rs
