sqlx_build_trust_core/
logger.rs

1use crate::connection::LogSettings;
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 use sqlformat;
58
59pub struct QueryLogger<'q> {
60    sql: &'q str,
61    rows_returned: u64,
62    rows_affected: u64,
63    start: Instant,
64    settings: LogSettings,
65}
66
67impl<'q> QueryLogger<'q> {
68    pub fn new(sql: &'q str, settings: LogSettings) -> Self {
69        Self {
70            sql,
71            rows_returned: 0,
72            rows_affected: 0,
73            start: Instant::now(),
74            settings,
75        }
76    }
77
78    pub fn increment_rows_returned(&mut self) {
79        self.rows_returned += 1;
80    }
81
82    pub fn increase_rows_affected(&mut self, n: u64) {
83        self.rows_affected += n;
84    }
85
86    pub fn finish(&self) {
87        let elapsed = self.start.elapsed();
88
89        let was_slow = elapsed >= self.settings.slow_statements_duration;
90
91        let lvl = if was_slow {
92            self.settings.slow_statements_level
93        } else {
94            self.settings.statements_level
95        };
96
97        if let Some((tracing_level, log_level)) = private_level_filter_to_levels(lvl) {
98            // The enabled level could be set from either tracing world or log world, so check both
99            // to see if logging should be enabled for our level
100            let log_is_enabled = log::log_enabled!(target: "sqlx::query", log_level)
101                || private_tracing_dynamic_enabled!(target: "sqlx::query", tracing_level);
102            if log_is_enabled {
103                let mut summary = parse_query_summary(&self.sql);
104
105                let sql = if summary != self.sql {
106                    summary.push_str(" …");
107                    format!(
108                        "\n\n{}\n",
109                        sqlformat::format(
110                            &self.sql,
111                            &sqlformat::QueryParams::None,
112                            sqlformat::FormatOptions::default()
113                        )
114                    )
115                } else {
116                    String::new()
117                };
118
119                if was_slow {
120                    private_tracing_dynamic_event!(
121                        target: "sqlx::query",
122                        tracing_level,
123                        summary,
124                        db.statement = sql,
125                        rows_affected = self.rows_affected,
126                        rows_returned = self.rows_returned,
127                        // Human-friendly - includes units (usually ms). Also kept for backward compatibility
128                        ?elapsed,
129                        // Search friendly - numeric
130                        elapsed_secs = elapsed.as_secs_f64(),
131                        // When logging to JSON, one can trigger alerts from the presence of this field.
132                        slow_threshold=?self.settings.slow_statements_duration,
133                        // Make sure to use "slow" in the message as that's likely
134                        // what people will grep for.
135                        "slow statement: execution time exceeded alert threshold"
136                    );
137                } else {
138                    private_tracing_dynamic_event!(
139                        target: "sqlx::query",
140                        tracing_level,
141                        summary,
142                        db.statement = sql,
143                        rows_affected = self.rows_affected,
144                        rows_returned = self.rows_returned,
145                        // Human-friendly - includes units (usually ms). Also kept for backward compatibility
146                        ?elapsed,
147                        // Search friendly - numeric
148                        elapsed_secs = elapsed.as_secs_f64(),
149                    );
150                }
151            }
152        }
153    }
154}
155
156impl<'q> Drop for QueryLogger<'q> {
157    fn drop(&mut self) {
158        self.finish();
159    }
160}
161
162pub fn parse_query_summary(sql: &str) -> String {
163    // For now, just take the first 4 words
164    sql.split_whitespace()
165        .take(4)
166        .collect::<Vec<&str>>()
167        .join(" ")
168}
sqlx_build_trust_core/logger.rs

sqlx_build_trust_core/
logger.rs
