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

            
7
use std::num::NonZeroU8;
8

            
9
use 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.
13
7
pub(super) fn new_formatter(
14
7
    granularity: std::time::Duration,
15
7
) -> impl tracing_subscriber::fmt::time::FormatTime {
16
7
    LogPrecision::from_duration(granularity).timer()
17
7
}
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))]
25
enum 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.
50
fn 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)]
59
enum 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.
72
struct 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

            
80
impl 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
7
    fn from_duration(dur: std::time::Duration) -> Self {
89
        // Round any fraction greater than 1 up to next second.
90
7
        let seconds = match (dur.as_secs(), dur.subsec_nanos()) {
91
            (0, _) => 0,
92
7
            (a, 0) => a,
93
            (a, _) => a + 1,
94
        };
95

            
96
        // Anything above one hour minus one minute will round to one hour.
97
7
        if seconds >= 3541 {
98
            // This is the lowest precision we have.
99
            LogPrecision::Hours
100
7
        } else if seconds >= 60 {
101
            let minutes = (seconds + 59) / 60; // TODO MSRV div_ceil once it exists.
102
            assert!((1..=59).contains(&minutes));
103
            LogPrecision::Minutes(minutes.try_into().expect("Math bug"))
104
7
        } else if seconds >= 1 {
105
7
            assert!((1..=59).contains(&seconds));
106
7
            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
7
    }
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
7
    fn timer(&self) -> LogTimer {
120
        use LogPrecision::*;
121
7
        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
7
            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
7
        let formatter = format_description::parse_owned::<2>(&format_str)
134
7
            .expect("Couldn't parse a built-in time format string");
135
7
        let rounder = match self {
136
7
            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
7
        LogTimer { rounder, formatter }
146
7
    }
147
}
148

            
149
/// An error that occurs while trying to format the time.
150
///
151
/// Internal.
152
#[derive(thiserror::Error, Debug)]
153
#[non_exhaustive]
154
enum 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

            
170
impl 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
105
    fn round(&self, when: time::OffsetDateTime) -> Result<time::OffsetDateTime, TimeFmtError> {
176
105
        // NOTE: This function really mustn't panic.  We try to log any panics
177
105
        // that we encounter, and if logging itself can panic, we're in a
178
105
        // potential heap of trouble.
179
105
        //
180
105
        // This danger is somewhat ameliorated by the behavior of the default
181
105
        // panic handler, which detects nested panics and aborts in response.
182
105
        // Thus, if we ever discard that handler, we need to be sure to
183
105
        // reimplement nested panic detection.
184
105
        //
185
105
        // Alternatively, we _could_ nest this functionality within
186
105
        // `catch_unwind`.  But I'm not sure that the overhead there would be
187
105
        // acceptable: Logging can be performance sensitive.
188
105

            
189
105
        use TimeRounder::*;
190
105
        /// Round `inp` down to the nearest multiple of `granularity`.
191
105
        fn round_down(inp: u8, granularity: NonZeroU8) -> u8 {
192
            inp - (inp % granularity)
193
        }
194
105

            
195
105
        Ok(match self {
196
105
            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
105
    }
205
}
206

            
207
impl LogTimer {
208
    /// Convert `when` to a string with appropriate rounding.
209
105
    fn time_to_string(&self, when: time::OffsetDateTime) -> Result<String, TimeFmtError> {
210
105
        // See NOTE above: This function mustn't panic.
211
105
        Ok(self.rounder.round(when)?.format(&self.formatter)?)
212
105
    }
213
}
214

            
215
impl tracing_subscriber::fmt::time::FormatTime for LogTimer {
216
105
    fn format_time(&self, w: &mut tracing_subscriber::fmt::format::Writer<'_>) -> std::fmt::Result {
217
105
        // See NOTE above: This function mustn't panic.
218
105
        w.write_str(
219
105
            &self
220
105
                .time_to_string(time::OffsetDateTime::now_utc())
221
105
                .map_err(|_| std::fmt::Error)?,
222
        )
223
105
    }
224
}
225

            
226
#[cfg(test)]
227
mod 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::print_stderr)]
233
    #![allow(clippy::print_stdout)]
234
    #![allow(clippy::single_char_pattern)]
235
    #![allow(clippy::unwrap_used)]
236
    #![allow(clippy::unchecked_duration_subtraction)]
237
    #![allow(clippy::useless_vec)]
238
    #![allow(clippy::needless_pass_by_value)]
239
    //! <!-- @@ end test lint list maintained by maint/add_warning @@ -->
240

            
241
    use super::*;
242
    use std::time::Duration;
243

            
244
    #[test]
245
    fn ilog() {
246
        assert_eq!(ilog10_roundup(0), 0);
247
        assert_eq!(ilog10_roundup(1), 0);
248
        assert_eq!(ilog10_roundup(2), 1);
249
        assert_eq!(ilog10_roundup(9), 1);
250
        assert_eq!(ilog10_roundup(10), 1);
251
        assert_eq!(ilog10_roundup(11), 2);
252
        assert_eq!(ilog10_roundup(99), 2);
253
        assert_eq!(ilog10_roundup(100), 2);
254
        assert_eq!(ilog10_roundup(101), 3);
255
        assert_eq!(ilog10_roundup(99_999_999), 8);
256
        assert_eq!(ilog10_roundup(100_000_000), 8);
257
        assert_eq!(ilog10_roundup(100_000_001), 9);
258
        assert_eq!(ilog10_roundup(999_999_999), 9);
259
        assert_eq!(ilog10_roundup(1_000_000_000), 9);
260
        assert_eq!(ilog10_roundup(1_000_000_001), 10);
261

            
262
        assert_eq!(ilog10_roundup(u32::MAX), 10);
263
    }
264

            
265
    #[test]
266
    fn precision_from_duration() {
267
        use LogPrecision::*;
268
        fn check(sec: u64, nanos: u32, expected: LogPrecision) {
269
            assert_eq!(
270
                LogPrecision::from_duration(Duration::new(sec, nanos)),
271
                expected,
272
            );
273
        }
274

            
275
        check(0, 0, Subseconds(9));
276
        check(0, 1, Subseconds(9));
277
        check(0, 5, Subseconds(8));
278
        check(0, 10, Subseconds(8));
279
        check(0, 1_000, Subseconds(6));
280
        check(0, 1_000_000, Subseconds(3));
281
        check(0, 99_000_000, Subseconds(1));
282
        check(0, 100_000_000, Subseconds(1));
283
        check(0, 200_000_000, Seconds(1));
284

            
285
        check(1, 0, Seconds(1));
286
        check(1, 1, Seconds(2));
287
        check(30, 0, Seconds(30));
288
        check(59, 0, Seconds(59));
289

            
290
        check(59, 1, Minutes(1));
291
        check(60, 0, Minutes(1));
292
        check(60, 1, Minutes(2));
293
        check(60 * 59, 0, Minutes(59));
294

            
295
        check(60 * 59, 1, Hours);
296
        check(3600, 0, Hours);
297
        check(86400 * 365, 0, Hours);
298
    }
299

            
300
    #[test]
301
    fn test_formatting() {
302
        let when = humantime::parse_rfc3339("2023-07-05T04:15:36.123456789Z")
303
            .unwrap()
304
            .into();
305
        let check = |precision: LogPrecision, expected| {
306
            assert_eq!(&precision.timer().time_to_string(when).unwrap(), expected);
307
        };
308
        check(LogPrecision::Hours, "2023-07-05T04:00:00Z");
309
        check(LogPrecision::Minutes(15), "2023-07-05T04:15:00Z");
310
        check(LogPrecision::Minutes(10), "2023-07-05T04:10:00Z");
311
        check(LogPrecision::Minutes(4), "2023-07-05T04:12:00Z");
312
        check(LogPrecision::Minutes(1), "2023-07-05T04:15:00Z");
313
        check(LogPrecision::Seconds(50), "2023-07-05T04:15:00Z");
314
        check(LogPrecision::Seconds(30), "2023-07-05T04:15:30Z");
315
        check(LogPrecision::Seconds(20), "2023-07-05T04:15:20Z");
316
        check(LogPrecision::Seconds(1), "2023-07-05T04:15:36Z");
317
        check(LogPrecision::Subseconds(1), "2023-07-05T04:15:36.1Z");
318
        check(LogPrecision::Subseconds(2), "2023-07-05T04:15:36.12Z");
319
        check(LogPrecision::Subseconds(7), "2023-07-05T04:15:36.1234567Z");
320
        check(
321
            LogPrecision::Subseconds(9),
322
            "2023-07-05T04:15:36.123456789Z",
323
        );
324
    }
325
}