arti/logging/
time.rs

Help
1//! Support logging the time with different levels of precision.
2//
3// TODO: We might want to move this to a lower-level crate if it turns out to be
4// generally useful: and it might, if we are encouraging the use of `tracing`
5// with arti!  If we do this, we need to clean up the API a little.
6
7use std::num::NonZeroU8;
8
9use time::format_description;
10
11/// Construct a new [`FormatTime`](tracing_subscriber::fmt::time::FormatTime)
12/// from a given user-supplied description of the desired log granularity.
13pub(super) fn new_formatter(
14    granularity: std::time::Duration,
15) -> impl tracing_subscriber::fmt::time::FormatTime {
16    LogPrecision::from_duration(granularity).timer()
17}
18
19/// Instructions for what degree of precision to use for our log times.
20//
21// (This is a separate type from `LogTimer` so that we can test our parsing
22// and our implementation independently.)
23#[derive(Clone, Debug)]
24#[cfg_attr(test, derive(Copy, Eq, PartialEq))]
25enum LogPrecision {
26    /// Display up to this many significant digits when logging.
27    ///
28    /// System limitations will also limit the number of digits displayed.
29    ///
30    /// Must be in range 1..9.
31    Subseconds(u8),
32    /// Before logging, round the number of seconds down to the nearest
33    /// multiple of this number within the current minute.
34    ///
35    /// Must be in range 1..59.
36    Seconds(u8),
37    /// Before logging, round the number of minutes down to the nearest multiple
38    /// of this number within the current hour.
39    ///
40    /// Must be in range 1..59.
41    Minutes(u8),
42
43    /// Before logging, round to down to the nearest hour.
44    Hours,
45}
46
47/// Compute the smallest n such that 10^n >= x.
48///
49/// Since the input is a u32, this will return a value in the range 0..10.
50fn ilog10_roundup(x: u32) -> u8 {
51    x.saturating_sub(1)
52        .checked_ilog10()
53        .map(|x| (x + 1) as u8)
54        .unwrap_or(0)
55}
56
57/// Describe how to compute the current time.
58#[derive(Clone, Debug)]
59enum TimeRounder {
60    /// Just take the current time; any transformation will be done by the
61    /// formatter.
62    Verbatim,
63    /// Round the minutes within the hours down to the nearest multiple of
64    /// this granularity.
65    RoundMinutes(NonZeroU8),
66    /// Round the seconds within the minute down to the nearest multiple of
67    /// this granularity.
68    RoundSeconds(NonZeroU8),
69}
70
71/// Actual type to implement log formatting.
72struct LogTimer {
73    /// Source that knows how to compute a time, rounded as necessary.
74    rounder: TimeRounder,
75    /// Formatter that knows how to format the time, discarding fields as
76    /// necessary.
77    formatter: format_description::OwnedFormatItem,
78}
79
80impl LogPrecision {
81    /// Convert a `Duration` into a LogPrecision that rounds the time displayed
82    /// in log messages to intervals _no more precise_ than the interval
83    /// specified in Duration.
84    ///
85    /// (As an exception, we do not support granularities greater than 1 hour.
86    /// If you specify a granularity greater than an hour, we just give you a
87    /// one-hour granularity.)
88    fn from_duration(dur: std::time::Duration) -> Self {
89        // Round any fraction greater than 1 up to next second.
90        let seconds = match (dur.as_secs(), dur.subsec_nanos()) {
91            (0, _) => 0,
92            (a, 0) => a,
93            (a, _) => a + 1,
94        };
95
96        // Anything above one hour minus one minute will round to one hour.
97        if seconds >= 3541 {
98            // This is the lowest precision we have.
99            LogPrecision::Hours
100        } else if seconds >= 60 {
101            let minutes = seconds.div_ceil(60);
102            assert!((1..=59).contains(&minutes));
103            LogPrecision::Minutes(minutes.try_into().expect("Math bug"))
104        } else if seconds >= 1 {
105            assert!((1..=59).contains(&seconds));
106            LogPrecision::Seconds(seconds.try_into().expect("Math bug"))
107        } else {
108            let ilog10 = ilog10_roundup(dur.subsec_nanos());
109            if ilog10 >= 9 {
110                LogPrecision::Seconds(1)
111            } else {
112                LogPrecision::Subseconds(9 - ilog10)
113            }
114        }
115    }
116
117    /// Convert a LogPrecision (which specifies the precision we want) into a
118    /// LogTimer (which can be used to format times in the log)
119    fn timer(&self) -> LogTimer {
120        use LogPrecision::*;
121        let format_str = match self {
122            Hours => "[year]-[month]-[day]T[hour repr:24]:00:00Z".to_string(),
123            Minutes(_) => "[year]-[month]-[day]T[hour repr:24]:[minute]:00Z".to_string(),
124            Seconds(_) => "[year]-[month]-[day]T[hour repr:24]:[minute]:[second]Z".to_string(),
125            Subseconds(significant_digits) => {
126                assert!(*significant_digits >= 1 && *significant_digits <= 9);
127                format!(
128                    "[year]-[month]-[day]T[hour]:[minute]:[second].[subsecond digits:{}]Z",
129                    significant_digits
130                )
131            }
132        };
133        let formatter = format_description::parse_owned::<2>(&format_str)
134            .expect("Couldn't parse a built-in time format string");
135        let rounder = match self {
136            Hours | Minutes(1) | Seconds(1) | Subseconds(_) => TimeRounder::Verbatim,
137            Minutes(granularity) => {
138                TimeRounder::RoundMinutes((*granularity).try_into().expect("Math bug"))
139            }
140            Seconds(granularity) => {
141                TimeRounder::RoundSeconds((*granularity).try_into().expect("Math bug"))
142            }
143        };
144
145        LogTimer { rounder, formatter }
146    }
147}
148
149/// An error that occurs while trying to format the time.
150///
151/// Internal.
152#[derive(thiserror::Error, Debug)]
153#[non_exhaustive]
154enum TimeFmtError {
155    /// The time crate wouldn't let us replace a field.
156    ///
157    /// This indicates that the value we were trying to use there was invalid,
158    /// and so our math must have been wrong.
159    #[error("Internal error while trying to round the time.")]
160    Rounding(#[from] time::error::ComponentRange),
161
162    /// The time crate wouldn't let us format a value.
163    ///
164    /// This indicates that our formatters were busted, and so we probably have
165    /// a programming error.
166    #[error("`time` couldn't format this time.")]
167    TimeFmt(#[from] time::error::Format),
168}
169
170impl TimeRounder {
171    /// Round `when` down according to this `TimeRounder`.
172    ///
173    /// Note that we round fields minimally: we don't round any fields that the
174    /// associated formatter will not display.
175    fn round(&self, when: time::OffsetDateTime) -> Result<time::OffsetDateTime, TimeFmtError> {
176        // NOTE: This function really mustn't panic.  We try to log any panics
177        // that we encounter, and if logging itself can panic, we're in a
178        // potential heap of trouble.
179        //
180        // This danger is somewhat ameliorated by the behavior of the default
181        // panic handler, which detects nested panics and aborts in response.
182        // Thus, if we ever discard that handler, we need to be sure to
183        // reimplement nested panic detection.
184        //
185        // Alternatively, we _could_ nest this functionality within
186        // `catch_unwind`.  But I'm not sure that the overhead there would be
187        // acceptable: Logging can be performance sensitive.
188
189        use TimeRounder::*;
190        /// Round `inp` down to the nearest multiple of `granularity`.
191        fn round_down(inp: u8, granularity: NonZeroU8) -> u8 {
192            inp - (inp % granularity)
193        }
194
195        Ok(match self {
196            Verbatim => when,
197            RoundMinutes(granularity) => {
198                when.replace_minute(round_down(when.minute(), *granularity))?
199            }
200            RoundSeconds(granularity) => {
201                when.replace_second(round_down(when.second(), *granularity))?
202            }
203        })
204    }
205}
206
207impl LogTimer {
208    /// Convert `when` to a string with appropriate rounding.
209    fn time_to_string(&self, when: time::OffsetDateTime) -> Result<String, TimeFmtError> {
210        // See NOTE above: This function mustn't panic.
211        Ok(self.rounder.round(when)?.format(&self.formatter)?)
212    }
213}
214
215impl tracing_subscriber::fmt::time::FormatTime for LogTimer {
216    fn format_time(&self, w: &mut tracing_subscriber::fmt::format::Writer<'_>) -> std::fmt::Result {
217        // See NOTE above: This function mustn't panic.
218        w.write_str(
219            &self
220                .time_to_string(time::OffsetDateTime::now_utc())
221                .map_err(|_| std::fmt::Error)?,
222        )
223    }
224}
225
226#[cfg(test)]
227mod test {
228    // @@ begin test lint list maintained by maint/add_warning @@
229    #![allow(clippy::bool_assert_comparison)]
230    #![allow(clippy::clone_on_copy)]
231    #![allow(clippy::dbg_macro)]
232    #![allow(clippy::mixed_attributes_style)]
233    #![allow(clippy::print_stderr)]
234    #![allow(clippy::print_stdout)]
235    #![allow(clippy::single_char_pattern)]
236    #![allow(clippy::unwrap_used)]
237    #![allow(clippy::unchecked_duration_subtraction)]
238    #![allow(clippy::useless_vec)]
239    #![allow(clippy::needless_pass_by_value)]
240    //! <!-- @@ end test lint list maintained by maint/add_warning @@ -->
241
242    use super::*;
243    use std::time::Duration;
244
245    #[test]
246    fn ilog() {
247        assert_eq!(ilog10_roundup(0), 0);
248        assert_eq!(ilog10_roundup(1), 0);
249        assert_eq!(ilog10_roundup(2), 1);
250        assert_eq!(ilog10_roundup(9), 1);
251        assert_eq!(ilog10_roundup(10), 1);
252        assert_eq!(ilog10_roundup(11), 2);
253        assert_eq!(ilog10_roundup(99), 2);
254        assert_eq!(ilog10_roundup(100), 2);
255        assert_eq!(ilog10_roundup(101), 3);
256        assert_eq!(ilog10_roundup(99_999_999), 8);
257        assert_eq!(ilog10_roundup(100_000_000), 8);
258        assert_eq!(ilog10_roundup(100_000_001), 9);
259        assert_eq!(ilog10_roundup(999_999_999), 9);
260        assert_eq!(ilog10_roundup(1_000_000_000), 9);
261        assert_eq!(ilog10_roundup(1_000_000_001), 10);
262
263        assert_eq!(ilog10_roundup(u32::MAX), 10);
264    }
265
266    #[test]
267    fn precision_from_duration() {
268        use LogPrecision::*;
269        fn check(sec: u64, nanos: u32, expected: LogPrecision) {
270            assert_eq!(
271                LogPrecision::from_duration(Duration::new(sec, nanos)),
272                expected,
273            );
274        }
275
276        check(0, 0, Subseconds(9));
277        check(0, 1, Subseconds(9));
278        check(0, 5, Subseconds(8));
279        check(0, 10, Subseconds(8));
280        check(0, 1_000, Subseconds(6));
281        check(0, 1_000_000, Subseconds(3));
282        check(0, 99_000_000, Subseconds(1));
283        check(0, 100_000_000, Subseconds(1));
284        check(0, 200_000_000, Seconds(1));
285
286        check(1, 0, Seconds(1));
287        check(1, 1, Seconds(2));
288        check(30, 0, Seconds(30));
289        check(59, 0, Seconds(59));
290
291        check(59, 1, Minutes(1));
292        check(60, 0, Minutes(1));
293        check(60, 1, Minutes(2));
294        check(60 * 59, 0, Minutes(59));
295
296        check(60 * 59, 1, Hours);
297        check(3600, 0, Hours);
298        check(86400 * 365, 0, Hours);
299    }
300
301    #[test]
302    fn test_formatting() {
303        let when = humantime::parse_rfc3339("2023-07-05T04:15:36.123456789Z")
304            .unwrap()
305            .into();
306        let check = |precision: LogPrecision, expected| {
307            assert_eq!(&precision.timer().time_to_string(when).unwrap(), expected);
308        };
309        check(LogPrecision::Hours, "2023-07-05T04:00:00Z");
310        check(LogPrecision::Minutes(15), "2023-07-05T04:15:00Z");
311        check(LogPrecision::Minutes(10), "2023-07-05T04:10:00Z");
312        check(LogPrecision::Minutes(4), "2023-07-05T04:12:00Z");
313        check(LogPrecision::Minutes(1), "2023-07-05T04:15:00Z");
314        check(LogPrecision::Seconds(50), "2023-07-05T04:15:00Z");
315        check(LogPrecision::Seconds(30), "2023-07-05T04:15:30Z");
316        check(LogPrecision::Seconds(20), "2023-07-05T04:15:20Z");
317        check(LogPrecision::Seconds(1), "2023-07-05T04:15:36Z");
318        check(LogPrecision::Subseconds(1), "2023-07-05T04:15:36.1Z");
319        check(LogPrecision::Subseconds(2), "2023-07-05T04:15:36.12Z");
320        check(LogPrecision::Subseconds(7), "2023-07-05T04:15:36.1234567Z");
321        cfg_if::cfg_if! {
322            if #[cfg(windows)] {
323                // Windows has a 100-nanosecond precision, see
324                // https://learn.microsoft.com/en-us/windows/win32/sysinfo/about-time
325                let expected = "2023-07-05T04:15:36.123456700Z";
326            } else {
327                let expected = "2023-07-05T04:15:36.123456789Z";
328            }
329        }
330        check(LogPrecision::Subseconds(9), expected);
331    }
332}
arti/logging/time.rs

arti/logging/
time.rs
