sqlx_core/
logger.rs

1use crate::{connection::LogSettings, sql_str::SqlStr};
2use std::time::Instant;
3
4// Yes these look silly. `tracing` doesn't currently support dynamic levels
5// https://github.com/tokio-rs/tracing/issues/372
6#[doc(hidden)]
7#[macro_export]
8macro_rules! private_tracing_dynamic_enabled {
9    (target: $target:expr, $level:expr) => {{
10        use ::tracing::Level;
11
12        match $level {
13            Level::ERROR => ::tracing::enabled!(target: $target, Level::ERROR),
14            Level::WARN => ::tracing::enabled!(target: $target, Level::WARN),
15            Level::INFO => ::tracing::enabled!(target: $target, Level::INFO),
16            Level::DEBUG => ::tracing::enabled!(target: $target, Level::DEBUG),
17            Level::TRACE => ::tracing::enabled!(target: $target, Level::TRACE),
18        }
19    }};
20    ($level:expr) => {{
21        $crate::private_tracing_dynamic_enabled!(target: module_path!(), $level)
22    }};
23}
24
25#[doc(hidden)]
26#[macro_export]
27macro_rules! private_tracing_dynamic_event {
28    (target: $target:expr, $level:expr, $($args:tt)*) => {{
29        use ::tracing::Level;
30
31        match $level {
32            Level::ERROR => ::tracing::event!(target: $target, Level::ERROR, $($args)*),
33            Level::WARN => ::tracing::event!(target: $target, Level::WARN, $($args)*),
34            Level::INFO => ::tracing::event!(target: $target, Level::INFO, $($args)*),
35            Level::DEBUG => ::tracing::event!(target: $target, Level::DEBUG, $($args)*),
36            Level::TRACE => ::tracing::event!(target: $target, Level::TRACE, $($args)*),
37        }
38    }};
39}
40
41#[doc(hidden)]
42pub fn private_level_filter_to_levels(
43    filter: log::LevelFilter,
44) -> Option<(tracing::Level, log::Level)> {
45    let tracing_level = match filter {
46        log::LevelFilter::Error => Some(tracing::Level::ERROR),
47        log::LevelFilter::Warn => Some(tracing::Level::WARN),
48        log::LevelFilter::Info => Some(tracing::Level::INFO),
49        log::LevelFilter::Debug => Some(tracing::Level::DEBUG),
50        log::LevelFilter::Trace => Some(tracing::Level::TRACE),
51        log::LevelFilter::Off => None,
52    };
53
54    tracing_level.zip(filter.to_level())
55}
56
57pub(crate) fn private_level_filter_to_trace_level(
58    filter: log::LevelFilter,
59) -> Option<tracing::Level> {
60    private_level_filter_to_levels(filter).map(|(level, _)| level)
61}
62
63pub struct QueryLogger {
64    sql: SqlStr,
65    rows_returned: u64,
66    rows_affected: u64,
67    start: Instant,
68    settings: LogSettings,
69}
70
71impl QueryLogger {
72    pub fn new(sql: SqlStr, settings: LogSettings) -> Self {
73        Self {
74            sql,
75            rows_returned: 0,
76            rows_affected: 0,
77            start: Instant::now(),
78            settings,
79        }
80    }
81
82    pub fn increment_rows_returned(&mut self) {
83        self.rows_returned += 1;
84    }
85
86    pub fn increase_rows_affected(&mut self, n: u64) {
87        self.rows_affected += n;
88    }
89
90    pub fn sql(&self) -> &SqlStr {
91        &self.sql
92    }
93
94    pub fn finish(&self) {
95        let elapsed = self.start.elapsed();
96
97        let was_slow = elapsed >= self.settings.slow_statements_duration;
98
99        let lvl = if was_slow {
100            self.settings.slow_statements_level
101        } else {
102            self.settings.statements_level
103        };
104
105        if let Some((tracing_level, log_level)) = private_level_filter_to_levels(lvl) {
106            // The enabled level could be set from either tracing world or log world, so check both
107            // to see if logging should be enabled for our level
108            let log_is_enabled = log::log_enabled!(target: "sqlx::query", log_level)
109                || private_tracing_dynamic_enabled!(target: "sqlx::query", tracing_level);
110            if log_is_enabled {
111                let mut summary = parse_query_summary(self.sql.as_str());
112
113                let sql = if summary != self.sql.as_str() {
114                    summary.push_str(" …");
115                    format!("\n\n{}\n", self.sql.as_str())
116                } else {
117                    String::new()
118                };
119
120                if was_slow {
121                    private_tracing_dynamic_event!(
122                        target: "sqlx::query",
123                        tracing_level,
124                        summary,
125                        db.statement = sql,
126                        rows_affected = self.rows_affected,
127                        rows_returned = self.rows_returned,
128                        // Human-friendly - includes units (usually ms). Also kept for backward compatibility
129                        ?elapsed,
130                        // Search friendly - numeric
131                        elapsed_secs = elapsed.as_secs_f64(),
132                        // When logging to JSON, one can trigger alerts from the presence of this field.
133                        slow_threshold=?self.settings.slow_statements_duration,
134                        // Make sure to use "slow" in the message as that's likely
135                        // what people will grep for.
136                        "slow statement: execution time exceeded alert threshold"
137                    );
138                } else {
139                    private_tracing_dynamic_event!(
140                        target: "sqlx::query",
141                        tracing_level,
142                        summary,
143                        db.statement = sql,
144                        rows_affected = self.rows_affected,
145                        rows_returned = self.rows_returned,
146                        // Human-friendly - includes units (usually ms). Also kept for backward compatibility
147                        ?elapsed,
148                        // Search friendly - numeric
149                        elapsed_secs = elapsed.as_secs_f64(),
150                    );
151                }
152            }
153        }
154    }
155}
156
157impl Drop for QueryLogger {
158    fn drop(&mut self) {
159        self.finish();
160    }
161}
162
163pub fn parse_query_summary(sql: &str) -> String {
164    // For now, just take the first 4 words
165    sql.split_whitespace()
166        .take(4)
167        .collect::<Vec<&str>>()
168        .join(" ")
169}
sqlx_core/logger.rs

sqlx_core/
logger.rs
