tag2upload_service_manager/

tracing_logrotate.rs

//! Better replacement for `tracing_appender::rolling`
//!
//! Like `tracing_appender::rolling` but:
//!
//!  * Can write multiple series of output files,
//!    each with a different filter level.
//!  * With some bugs fixed.
//!  * We use the word `rotate` not the anomalous `roll`.
//!
//! # Rationale
//!
//! `tracing` is very bad.  We're only using it because `rocket` does
//! (and because other parts of the async Rust ecosystem like it).
//!
//! One of the biggest problems is that the model is not documented.
//! The composition of the various pieces is extremely confusing
//! (and, very probably, incoherent).
//! See 
//! [#2141](https://github.com/tokio-rs/tracing/issues/2141#issuecomment-1143369647);
//! this also seems to be generating many bug reports from confused users
//! who haven't managed to analyse the situation as well as that.
//! For this reason, we don't want to try to have multiple `Subscriber`s
//! or try to use `Layer`s.
//! Instead, we do all the level filtering directly, here.
//!
//! I tried using `RollingFileAppender` but tripped over a bug
//! that broke my tests:
//! it doesn't rotate logfiles until the first entry is written
//! ([#2937](https://github.com/tokio-rs/tracing/issues/2937)).
//! Other tickets I saw in the upstream tracker didn't encourage me,
//! eg [#1932](https://github.com/tokio-rs/tracing/issues/1932).


#[cfg(test)]
use std::eprintln as tprintln;

#[cfg(not(test))]
macro_rules! tprintln { {$($x:tt)* } => {} }

use std::collections::{HashMap, BTreeMap};
use std::fmt::{self, Debug, Display};
use std::fs::{self, File};
use std::io::{self, LineWriter, Write as _};
use std::ops::Add;
use std::path::{Path, PathBuf};
use std::sync::{Mutex, MutexGuard};
use std::time::{Duration, SystemTime as RawSystemTime};

use chrono::{NaiveDateTime, NaiveTime, Weekday, Utc};
use chrono::{Datelike as _, Timelike as _};
use derive_more::{From, Into};
use itertools::Itertools;
use serde::{Deserialize, Deserializer, Serialize};
use thiserror::Error;
use tracing::{Level, Metadata};
use tracing::metadata::LevelFilter;
use tracing_subscriber::fmt::MakeWriter;

type DateTimeUtc = chrono::DateTime<Utc>;

#[cfg(test)]
use humantime_serde::re::humantime::format_rfc3339_nanos as f3339;

const SUFFIX: &str = ".log";

//---------- public API types ----------

#[derive(Copy, Clone, PartialEq, Eq, Debug)]
#[derive(strum::EnumString, strum::Display)]
#[derive(Serialize)]
#[cfg_attr(test, derive(strum::EnumIter))]
#[strum(serialize_all = "snake_case")]
#[serde(into = "String")]
pub enum Interval {
    Hour,
    Day,
    Week,
    Month,
}

pub struct Writer<'a> {
    level: Level,
    appender: &'a Appender,
}

#[derive(From, Into, Deserialize, Serialize, Debug, Default, Clone)]
#[serde(try_from = "ScheduleConfigSerde", into="ScheduleConfigSerde")]
#[cfg_attr(test, derive(Eq, PartialEq))]
pub struct ScheduleConfig(BTreeMap<LevelFilter, LevelConfig>);

pub struct Appender {
    inner: Mutex<Inner>,
}

#[derive(Clone, Debug, Deserialize, Serialize)]
#[cfg_attr(test, derive(Eq, PartialEq))]
pub struct LevelConfig {
    #[serde(default = "crate::config::u32_::<15>")]
    pub max_files: u32,
    pub interval: Interval,
}

//---------- principal internal types ----------

#[derive(PartialEq, Eq, Debug)]
struct Period {
    start: NaiveDateTime,
    interval: Interval,
}

struct Inner {
    common: Common,
    outputs: Vec<Output>,
}

struct Common {
    dir: PathBuf,
    tprov: TimeProvider,
    max_max_age_backstop: Duration,
}

struct Output {
    level: LevelFilter,
    config: LevelConfig,
    period: Period,
    file: OutputFile,
}

struct OutputFile {
    file: LineWriter<File>,
    path: PathBuf,
}

#[derive(Error, Debug)]
#[error("{}: {op}: {ioe}", path.display())]
struct Error {
    #[source]
    ioe: io::Error,
    path: PathBuf,
    op: String,
}

type ScheduleConfigSerde = HashMap<String, LevelConfig>;

//---------- time mocking/testing support types ----------

#[derive(Copy, Clone, Debug, Eq, PartialEq, Ord, PartialOrd)]
struct SystemTime(RawSystemTime);

enum TimeProvider {
    System,

    #[cfg(test)]
    Test(test::TestTimeProvider),
}

//==================== implementations ====================

//---------- principal impls ----------

impl Appender {
    pub fn new(dir: PathBuf, levels: &ScheduleConfig) -> io::Result<Self> {
        Self::new_with_time_provider(dir, levels, TimeProvider::System)
    }

    fn new_with_time_provider(
        dir: PathBuf,
        levels: &ScheduleConfig,
        tprov: TimeProvider,
    ) -> io::Result<Self> {
        let now = tprov.now();
        let max_max_age_backstop = levels.0.iter().map(|(_level, config)| {
            config.max_age_backstop()
        })
            .max()
            .unwrap_or(Duration::MAX);

        let common = Common { dir, tprov, max_max_age_backstop };
        let outputs = levels.0.iter()
            .filter(|(_, config)| config.max_files > 0)
            .map(|(&level, config)| {
                let period = Period::containing(now, config.interval);
                let file = common.open_file(now, level, &config, &period)?;
                let config = config.clone();
                Ok::<_, Error>(Output { level, config, period, file })
            }).try_collect()?;
        let inner = Mutex::new(Inner { common, outputs });
        Ok(Appender { inner })
    }

    fn lock(&self) -> MutexGuard<Inner> {
        self.inner.lock().expect("lock poisoned!")
    }

    fn make_writer_for_level<'a>(&'a self, level: Level) -> Writer<'a> {
        Writer {
            level,
            appender: &self,
        }
    }
}

impl Common {
    fn open_file(
        &self,
        now: SystemTime,
        level: LevelFilter,
        config: &LevelConfig,
        period: &Period,
    ) -> Result<OutputFile, Error> {
        let prefix = {
            let mut l = format!("{}_", level);
            l.make_ascii_lowercase();
            l
        };

        let this_leaf = format!("{prefix}{period}{SUFFIX}");
        let this_path = self.leaf2path(&this_leaf);

        tprintln!("XX R{} OPENING {}", f3339(RawSystemTime::now()), this_leaf);

        let this_file = File::options()
            .append(true)
            .create(true)
            .read(false)
            .truncate(false)
            .open(&this_path)
            .map_err(Error::err_mapper("open", &this_path))?;

        let mut del_candidates = vec![];
        let max_age_backstop = config.max_age_backstop();

        self.scan_for_expire(
            now,
            |del_leaf, age| {
                if age > self.max_max_age_backstop {
                    return self.delete_leaf(del_leaf, ">max_backstop");
                }
                if ! del_leaf.starts_with(&prefix) {
                    return Ok(())
                }
                if age > max_age_backstop && *del_leaf < *this_leaf {
                    self.delete_leaf(del_leaf, ">backstop")?;
                } else {
                    del_candidates.push(del_leaf.to_owned());
                }
                Ok(())
            },
        )?;

        // lexical, latest first
        del_candidates.sort_by(|a, b| b.cmp(a));

        while {
            del_candidates.len()
                >
            usize::try_from(config.max_files).unwrap_or(usize::MAX)
        } {
            let del_leaf = del_candidates.pop().expect("empty!");
            if del_leaf >= this_leaf { break; }
            self.delete_leaf(&del_leaf, "max_files")?;
        }

        Ok(OutputFile {
            file: LineWriter::new(this_file),
            path: this_path,
        })
    }

    fn leaf2path(&self, leaf: &str) -> PathBuf {
        let mut path = self.dir.clone();
        path.push(leaf);
        path
    }
}

impl Output {
    fn if_level(&mut self, event: Level) -> Option<&mut Self> {
        if event <= self.level { // Level <=> LevelFilter is backwards!!
            Some(self)
        } else {
            None
        }
    }

    fn consider_reopen(&mut self, common: &Common) -> Result<(), Error> {
        let now = common.tprov.now();
        let period = Period::containing(now, self.config.interval);
        if self.period == period { return Ok(()) }

        self.file.file.flush().map_err(self.err_mapper("flush"))?;
        let file = common.open_file(now, self.level, &self.config, &period)?;
        self.file = file;
        self.period = period;
        Ok(())
    }
}

//---------- expiry ----------

impl Common {
    fn scan_for_expire(
        &self,
        now: SystemTime,
        mut each_leaf: impl FnMut(&str, Duration) -> Result<(), Error>,
    ) -> Result<(), Error> {
        let err_mapper_readdir = || Error::err_mapper("read dir", &self.dir);

        for ent in fs::read_dir(&self.dir)
            .map_err(err_mapper_readdir())?
        {
            let ent = ent.map_err(err_mapper_readdir())?;
            let del_leaf = ent.file_name();
            let Ok(del_leaf) = <&str>::try_from(&*del_leaf)
            else { /* non-utf8 crap in this directory, ignore */ continue };

            tprintln!("{:37} SCAN {}", "", del_leaf);

            if !del_leaf.ends_with(&SUFFIX) { continue }

            let ent_path = ent.file_name();
            let ent_path = ent_path.as_ref();

            let age = (|| {
                let modified = ent
                    .metadata()
                    .map_err(Error::err_mapper("stat existing/old logfile",
                                               ent_path))?
                    .modified()
                    .map_err(Error::err_mapper("convert mtime", ent_path))?;
                let age = now.duration_since(&self.tprov, modified)
                    // Sometimes, Linux shows a file as having a modification
                    // time in the future.  WTF.  We use this only for
                    // calculating the age for expiry, and in that case
                    // zero will do nicely..  If the clock is badly broken,
                    // then zero will avoid us expiring things wrongly.
                    .unwrap_or_default();
                Ok(age)
            })()?;

            each_leaf(del_leaf, age)?;
        }
        Ok(())
    }

    fn delete_leaf(&self, del_leaf: &str, _why: &str) -> Result<(), Error> {
        tprintln!("    {_why:31} DELETE {}", del_leaf);

        let del_path = self.leaf2path(del_leaf);
        fs::remove_file(&del_path)
            .map_err(Error::err_mapper("remove old file", &del_path))?;
        Ok(())
    }
}

//---------- writer plumbing ----------

impl<'a> io::Write for Writer<'a> {
    fn write(&mut self, s: &[u8]) -> io::Result<usize> {
        let mut inner = self.appender.lock();
        let inner = &mut *inner;
        for o in &mut inner.outputs {
            if let Some(o) = o.if_level(self.level) {
                o.consider_reopen(&inner.common)?;
                o.file.file.write_all(s).map_err(o.err_mapper("write"))?;
            }
        }
        Ok(s.len())
    }
    fn flush(&mut self) -> io::Result<()> {
        let mut inner = self.appender.lock();
        let inner = &mut *inner;
        for o in &mut inner.outputs {
            if let Some(o) = o.if_level(self.level) {
                o.file.file.flush().map_err(o.err_mapper("write"))?;
            }
        }
        Ok(())
    }
}

impl<'a> MakeWriter<'a> for Appender {
    type Writer = Writer<'a>;

    fn make_writer(&'a self) -> Writer<'a> {
        self.make_writer_for_level(Level::ERROR /* sadly no ::MAX */)
    }
    fn make_writer_for(&'a self, meta: &Metadata<'_>) -> Writer<'a> {
        self.make_writer_for_level(*meta.level())
    }
}

//---------- Interval/Period calculations etc. ----------

impl LevelConfig {
    /// Backstop maximum age for any file (for this `LevelConfig`)
    ///
    /// In case we haven't actually be writing files, so there
    /// might not be enough to cause rotation.  Cap the data age.
    fn max_age_backstop(&self) -> Duration {
        // The oldest file might legitimately have an age of n+1 periods,
        // since maybe it was started right at the start of the period.
        self.interval.duration() * (self.max_files + 1)
    }
}

impl Period {
    pub fn containing(now: SystemTime, interval: Interval) -> Self {
        use Interval as I;
        let from_date = |d| NaiveDateTime::new(d, NaiveTime::MIN);
        let now = now.chrono_naive_utc();
        let start = match interval {
            I::Hour => {
                let hour = now.hour();
                NaiveDateTime::new(
                    now.date(),
                    NaiveTime::from_hms_opt(hour, 0, 0)
                        .expect("hour out of range?!")
                )
            }   
            I::Day => {
                from_date(now.date())
            }
            I::Week => {
                let week = now.date().week(Weekday::Sun);
                from_date(week.first_day())
            }
            I::Month => {
                let start = now.date().with_day0(0).expect("month no start!");
                from_date(start)
            }
        };
        Period { start, interval }
    }
}

impl Interval {
    pub fn duration(&self) -> Duration {
        use Interval as I;
        Duration::from_secs(match self {
            I::Hour => 3600,
            I::Day => 86400,
            I::Week => 86400 * 7,
            I::Month => 86400 * 31,
        })
    }
}

impl Display for Period {
    fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
        use Interval as I;
        let i = match self.interval {
            I::Hour => "%Y-%m-%dT%H",
            I::Day => "%Y-%m-%d",
            I::Week => "%Y-%m-%d+",
            I::Month => "%Y-%m",
        };
        write!(f, "{}", self.start.format(i))
    }
}

//---------- deserialisation and config support ----------

impl ScheduleConfig {
    pub fn most_verbose_level(&self) -> LevelFilter {
        self.0.keys().max().copied().unwrap_or(LevelFilter::OFF)
    }
}

impl TryFrom<ScheduleConfigSerde> for ScheduleConfig {
    type Error = tracing::level_filters::ParseLevelFilterError;

    fn try_from(hm: ScheduleConfigSerde) -> Result<Self, Self::Error> {
        let bm = hm.into_iter().map(|(k, v)| {
            let k: LevelFilter = k.parse()?;
            Ok::<_, Self::Error>((k, v))
        }).try_collect()?;
        Ok(ScheduleConfig(bm))
    }
}

impl From<ScheduleConfig> for ScheduleConfigSerde {
    fn from(sc: ScheduleConfig) -> Self {
        sc.0.into_iter().map(|(k, v)| {
            let mut k: String = k.to_string();
            k.make_ascii_lowercase();
            (k, v)
        }).collect()
    }
}

impl<'de> Deserialize<'de> for Interval {
    fn deserialize<D: Deserializer<'de>>(d: D) -> Result<Self, D::Error> {
        struct V;
        
        const EXP: &str = "log rotation interval";

        impl serde::de::Visitor<'_> for V {
            type Value = Interval;
            fn visit_str<E>(self, v: &str) -> Result<Self::Value, E>
            where E: serde::de::Error
            {
                v.parse().map_err(
                    |_| E::invalid_value(
                        serde::de::Unexpected::Str(v),
                        &EXP,
                    )
                )
            }
            fn expecting(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
                write!(f, "{EXP}")
            }
        }

        d.deserialize_str(V)
    }
}

impl From<Interval> for String {
    fn from(i: Interval) -> String { i.to_string() }
}

//---------- time mocking/testing ----------

// contains the cfg(test) impls, for convenience

impl TimeProvider {
    fn now(&self) -> SystemTime {
        use TimeProvider as TP;
        let now = RawSystemTime::now();
        match self {
            TP::System => SystemTime(now),

            #[cfg(test)]
            TP::Test(t) => {
                let mut t = TimeProvider::lock(t);
                tprintln!("TP R{} now", f3339(now));
                assert!(now >= t.last_seen);
                t.raw2pretend(now)
            }
        }
    }
}

impl SystemTime {
    fn duration_since(
        &self,
        t: &TimeProvider,
        file_age: RawSystemTime
    ) -> Result<Duration, std::time::SystemTimeError> {
        use TimeProvider as TP;
        let file_age = match t {
            TP::System => SystemTime(file_age),

            #[cfg(test)]
            TP::Test(t) => {
                let mut t = TimeProvider::lock(t);
                tprintln!("TP R{} duration_since", f3339(file_age));
                t.raw2pretend(file_age)
            },
        };
        self.0.duration_since(file_age.0)
    }

    fn chrono_naive_utc(self) -> NaiveDateTime {
        DateTimeUtc::from(self.0).naive_utc()
    }
}

impl Add<Duration> for SystemTime {
    type Output = SystemTime;
    fn add(self, rhs: Duration) -> SystemTime {
        SystemTime(self.0 + rhs)
    }
}

//---------- Error handling ----------

impl From<Error> for io::Error {
    fn from(e: Error) -> io::Error {
        io::Error::new(e.ioe.kind(), e)
    }
}

impl Output {
    fn err_mapper<'o>(&'o self, op: &'o str)
                      -> impl FnOnce(io::Error) -> Error + 'o
    {
        Error::err_mapper(op, &self.file.path)
    }
}

impl Error {
    fn err_mapper<'o>(op: &'o str, path: &'o Path)
                      -> impl FnOnce(io::Error) -> Error + 'o
    {
        |ioe| Error {
            ioe,
            path: path.to_owned(),
            op: op.to_owned(),
        }
    }
}

//==================== tests ====================

#[cfg(test)]
mod test {
    use super::*;
    use std::collections::BTreeSet;
    use std::cmp;
    use std::process::Command;
    use std::str::FromStr;
    use std::sync::Arc;

    use anyhow::Context;
    use humantime_serde::re::humantime;
    use itertools::izip;
    use serde_json::json;
    use strum::IntoEnumIterator;
    use test_temp_dir::test_temp_dir;
    use testresult::{TestError, TestResult};

    //---------- time mocking/testing ----------

    /// Guess at the filesystem timestamp resolution
    ///
    /// [SuS 2024](https://pubs.opengroup.org/onlinepubs/9799919799/basedefs/sys_stat.h.html):
    /// 
    /// > Upon assignment, file timestamps are immediately converted to the resolution of the file system by truncation \[...]
    ///
    /// So when the actual logging code creates a file,
    /// its mtime may be *before* a previous `RawSystemTime::now()`,
    /// by up to this value.
    /// Our approach is to try to segment [`RawSystemTime`] into ranges,
    /// which are treated as giving different simulated [`SystemTime`].
    /// We must sometimes sleep for this long, therefore,
    /// to make sure that file timestamps agree with the clock.
    ///
    /// On Linux the fs uses a cached value of the current time.
    /// [Austin Phillips on StackOverflow in 2013](https://stackoverflow.com/questions/14392975/timestamp-accuracy-on-ext4-sub-millsecond/14393315#14393315):
    /// > Internally, the ext4 filesystem code calls current_fs_time() which is the current cached kernel time \[...]
    ///
    /// There is, it seems, no way to find out the resolution.
    /// [Mike in 2011](https://unix.stackexchange.com/questions/11599/determine-file-system-timestamp-precision/11605#11605):
    /// > \[... ] but they don't seem to support any way to find out that piece of information.
    ///
    /// Current [pathconf(3)](https://manpages.debian.org/trixie/manpages-dev/pathconf.3.en.html)
    /// indeed doesn't show anything useful.
    ///
    /// So we hardcode this guess which, empirically, seems to work here.
    const FS_TIMESTAMP_RESOLUTION: Duration = Duration::from_millis(10);

    pub type TestTimeProvider = Arc<Mutex<TimeProviderInner>>;

    const TEST_START_3339: &str = "2024-10-01T19:39:45Z";

    pub struct TimeProviderInner {
        /// After `.0`. report `.1`
        pub since: Vec<(RawSystemTime, SystemTime)>,
        pub last_seen: RawSystemTime,
    }

    impl TimeProvider {
        pub fn lock(t: &TestTimeProvider) -> MutexGuard<TimeProviderInner> {
            t.lock().expect("tprov poison!")
        }
    }

    impl FromStr for SystemTime {
        type Err = humantime::TimestampError;
        fn from_str(s: &str) -> Result<Self, Self::Err> {
            humantime::parse_rfc3339(s).map(SystemTime)
        }
    }

    pub fn raw_system_time_start_period() -> RawSystemTime {
        let now = RawSystemTime::now();
        std::thread::sleep(FS_TIMESTAMP_RESOLUTION);
        now
    }

    impl TimeProviderInner {
        pub fn new_for_test() -> TestTimeProvider {
            TimeProviderInner::new(
                TEST_START_3339.parse().expect("bad constant")
            )
        }

        pub fn new(start: SystemTime) -> TestTimeProvider {
            let now = raw_system_time_start_period();
            tprintln!("TP R{} start       S{}", f3339(now), f3339(start.0));
            let tprov = TimeProviderInner {
                since: vec![(now, start)],
                last_seen: now,
            };
            Arc::new(Mutex::new(tprov))
        }

        pub fn raw2pretend(&mut self, raw: RawSystemTime) -> SystemTime {
            tprintln!("TP R{} raw2pretend", f3339(raw));
            self.last_seen = cmp::max(self.last_seen, raw);
            assert!(raw >= self.since[0].0, "{raw:?} {:?}", self.since);
            let ent_pos = self.since
                .binary_search_by(|ent| ent.0.cmp(&raw))
                .unwrap_or_else(|insert| insert - 1);
            let r = self.since[ent_pos].1;
            tprintln!("TP R{} raw2pretend S{}", f3339(raw), f3339(r.0));
            r
        }

        pub fn advance(&mut self, by_secs: u64) {
            let pstart = raw_system_time_start_period();
            assert!(pstart > self.last_seen);
            let last = self.since.last_mut().expect("empty!");
            assert!(pstart > last.0);
            let new_period = (pstart, last.1 + Duration::from_secs(by_secs));
            self.since.push(new_period);
        }
    }

    //---------- Ctx and common setup functions ----------

    struct Ctx {
        a: Appender,
        dir: PathBuf,
        tprov: TestTimeProvider,
    }

    impl Ctx {
        fn advance(&self, secs: u64) {
            TimeProvider::lock(&self.tprov)
                .advance(secs)
        }

        fn expect_files(&self, shell: &str) -> TestResult<()> {
            let shell = shell.chars()
                .filter(|c| !c.is_ascii_whitespace())
                .collect::<String>();

            let output = Command::new("bash")
                .args(["-ec", &format!("echo {shell}")])
                .output()?;
            assert!(output.status.success(), "{}", output.status);
            assert!(output.stderr.is_empty());
            let output = String::from_utf8(output.stdout)?;
            let expect = output
                .trim()
                .split_ascii_whitespace()
                .map(str::to_owned)
                .collect::<BTreeSet<_>>();

            let actual = fs::read_dir(&self.dir)?
                .map(|ent| {
                    let leaf = PathBuf::from(ent?.file_name())
                        .to_str().expect("non-utf8").to_owned();
                    Ok::<_, TestError>(leaf)
                })
                .filter_ok(|f| !(f == "." || f == ".."))
                .collect::<Result<BTreeSet<_>, _>>()?;
            assert_eq!(actual, expect,
                       "actual={actual:#?} expect={expect:#?}");
            Ok(())
        }

        fn shutdown(self) -> TestTimeProvider {
            let Ctx { tprov, .. } = self;
            tprov
        }
    }

    fn usual_levels() -> ScheduleConfig {
        use LevelFilter as L;
        use Interval as I;
        [
            (L::DEBUG, I::Hour),
            (L::INFO,  I::Day),
        ]
            .into_iter().map(|(level, interval)| {
                (level, LevelConfig { max_files: 5, interval })
            })
            .collect::<BTreeMap<_, _>>()
            .into()
    }

    fn setup(dir: &Path) -> TestResult<Ctx> {
        let tprov = TimeProviderInner::new_for_test();
        Ctx::new(dir, tprov)
    }

    impl Ctx {
        fn new(
            dir: &Path,
            tprov: TestTimeProvider,
        ) -> TestResult<Self> {
            Ctx::new_with_levels(dir, usual_levels(), tprov)
        }

        fn new_with_levels(
            dir: &Path,
            levels: ScheduleConfig,
            tprov: TestTimeProvider,
        ) -> TestResult<Self> {
            let a = Appender::new_with_time_provider(
                dir.to_owned(),
                &levels,
                TimeProvider::Test(tprov.clone()),
            )?;

            Ok(Ctx { a, tprov, dir: dir.to_owned() })
        }

        fn log(&self, m: impl Display) -> TestResult<()> {
            let mut w = self.a.make_writer();
            writeln!(w, "{m}")?;
            w.flush()?;
            Ok(())
        }
    }

    //---------- test cases ----------

    #[test]
    fn rotate() -> TestResult<()> { test_temp_dir!().used_by(|dir| {
        let c = setup(dir)?;
        c.log("started")?;
        for h in 0..7 {
            c.advance(3600);
            c.log(format!("h={h}"))?;
        }
        c.expect_files(
            r"{ debug_2024-10-{ 02T{ 02, 01, 00 }, 01T{ 23, 22 }},
                info_2024-10-{ 02, 01 } }.log"
        )?;
        Ok(())
    }).into_untracked() }

    #[test]
    fn level() -> TestResult<()> { test_temp_dir!().used_by(|dir| {
        let msg_error = "this message is an error";
        let msg_debug = "this message is debugging";

        let c = setup(dir)?;
        c.log(msg_error)?;

        {
            let mut w = c.a.make_writer_for_level(Level::DEBUG);
            writeln!(w, "{msg_debug}")?;
            w.flush()?;
        }

        let read = |leaf: &str| {
            let mut path = dir.to_owned();
            path.push(leaf);
            let s = fs::read_to_string(path)
                .context(leaf.to_owned())?;
            Ok::<_, anyhow::Error>(s)
        };

        assert_eq!(
            read("debug_2024-10-01T19.log")?,
            format!("{msg_error}\n{msg_debug}\n"),
        );
        assert_eq!(
            read("info_2024-10-01.log")?,
            format!("{msg_error}\n"),
        );

        Ok(())
    }).into_untracked() }

    #[test]
    fn restart() -> TestResult<()> { test_temp_dir!().used_by(|dir| {
        let c = setup(dir)?;
        c.log("earlier")?;

        let tprov = c.shutdown();

        TimeProvider::lock(&tprov).advance(86400);

        let c = Ctx::new(&dir, tprov)?;

        c.expect_files(
            r"{ debug_2024-10-02T19,
                info_2024-10-{ 02, 01 } }.log"
        )?;
        Ok(())
    }).into_untracked() }

    #[test]
    fn reconfig() -> TestResult<()> { test_temp_dir!().used_by(|dir| {
        use LevelFilter as L;
        let levels = [
            L::TRACE,
            L::DEBUG,
            L::INFO,
            L::WARN,
            L::ERROR,
        ];

        let c = Ctx::new_with_levels(
            &dir,
            izip!(
                levels.into_iter().cycle(),
                Interval::iter(),
            ).map(|(level, interval)| {
                (level, LevelConfig { max_files: 5, interval })
            }).collect::<BTreeMap<_, _>>().into(),
            TimeProviderInner::new_for_test(),
        )?;

        c.log("started")?;
        c.advance(86400 * 3);
        c.log("3 days later")?;

        c.expect_files(
            r"{ trace_2024-10-04T19,
                debug_2024-10-01,
                debug_2024-10-04,
                info_2024-09-29+,
                warn_2024-10 }.log"
        )?;

        let tprov = c.shutdown();

        TimeProvider::lock(&tprov).advance(86400 * 4);

        let c = Ctx::new(&dir, tprov)?;

        c.log("a further 4 days later")?;

        c.expect_files(
            r"{ trace_2024-10-04T19,
                debug_2024-10-08T19,
                info_2024-09-29+,
                info_2024-10-08,
                warn_2024-10 }.log"
        )?;

        c.advance(86400 * 3);
        c.log("surely that trace log from 2024-10-04 goes away")?;

        c.expect_files(
            r"{ debug_2024-10-11T19,
                info_2024-10-08,
                info_2024-10-11 }.log"
        )?;

        Ok(())
    }).into_untracked() }

    impl Period {
        fn start_system_time(&self) -> SystemTime {
            SystemTime(self.start.and_utc().into())
        }
    }

    #[test]
    fn intervals() -> TestResult<()> {
        let start: SystemTime = TEST_START_3339.parse()?;
        for i in Interval::iter() {
            tprintln!("{i:?}");
            let containing = |t| Period::containing(t, i);
            let mut t = start;
            for n in 0..30 {
                tprintln!("{i:?} {n} {}", f3339(t.0));
                let period = containing(t);
                let start = period.start_system_time();
                assert_eq!(period, containing(start));

                let d = if i != Interval::Month {
                    i.duration()
                } else {
                    let days = |days: u64| Duration::from_secs(days * 86400);
                    assert_eq!(i.duration(), days(31));

                    let month = period.start.month();
                    if month == 2 {
                        days(28) // next year, 2025, is not leap
                    } else if [4,6,9,11].contains(&month) {
                        days(30)
                    } else {
                        days(31)
                    }
                };
                let d_minus = d - Duration::from_secs(1);

                assert_eq!(period, containing(start + d_minus));
                let next_period = containing(start + d);
                assert_ne!(period, next_period);
                assert_ne!(period.to_string(), next_period.to_string());
                t = next_period.start_system_time();
            }
        }
        Ok(())
    }

    #[test]
    fn serde() -> TestResult<()> {
        let j = json!{ {
            "debug": {
                "interval": "hour",
                "max_files": 5,
            },
            "info": {
                "interval": "day",
                "max_files": 5,
            }
        } };

        let fj: ScheduleConfig = serde_json::from_value(j.clone())?;

        assert_eq!(fj, usual_levels());
        assert_eq!(serde_json::to_value(&fj)?, j);

        assert_eq!(fj.most_verbose_level(), LevelFilter::DEBUG);
        assert_eq!(
            ScheduleConfig(BTreeMap::new()).most_verbose_level(),
            LevelFilter::OFF,
        );

        Ok(())
    }
}