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

sqlx_core/
logger.rs
