Rewrite logging. (#859)

This PR implements all log handling with the exception of actual syslog in
Routinator itself. It also implements support for log rotation when logging
into files by re-opening the log file when receiving SIGUSR2.

Error handling for logging is now such that if trying to log to file or
syslog fails, Routinator will exit. It will also exit if it receives SIGUSR2
and can’t open the log file.

The motivation for this is that the log is used by many people to determine
issues with the RPKI repositories, so silently not having logs seems bad.
Also, not being able to log is a good indication for bigger problems to
come.

---------

Co-authored-by: Luuk Hendriks <mail@luukhendriks.eu>

Cargo.lock

@@ -75,12 +75,6 @@ dependencies = [
  "derive_arbitrary",
 ]
 
-[[package]]
-name = "arc-swap"
-version = "1.6.0"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "bddcadddf5e9015d310179a59bb28c4d4b9920ad0f11e8e14dbadf654890c9a6"
-
 [[package]]
 name = "autocfg"
 version = "1.1.0"
@@ -389,15 +383,6 @@ dependencies = [
  "instant",
 ]
 
-[[package]]
-name = "fern"
-version = "0.6.2"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "d9f0c14694cbd524c8720dd69b0e3179344f04ebb5f90f2e4a440c6ea3b2f1ee"
-dependencies = [
- "log",
-]
-
 [[package]]
 name = "filetime"
 version = "0.2.21"
@@ -835,17 +820,6 @@ dependencies = [
  "cfg-if",
 ]
 
-[[package]]
-name = "log-reroute"
-version = "0.1.8"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "741a3ba679a9a1d331319dda1c7d8f204e9f6760fd867e28576a45d17048bc02"
-dependencies = [
- "arc-swap",
- "log",
- "once_cell",
-]
-
 [[package]]
 name = "match_cfg"
 version = "0.1.0"
@@ -1211,15 +1185,14 @@ dependencies = [
  "crossbeam-queue",
  "crossbeam-utils",
  "dirs",
- "fern",
  "form_urlencoded",
  "futures",
  "hyper",
  "listenfd",
  "log",
- "log-reroute",
  "nix",
  "num_cpus",
+ "once_cell",
  "pin-project-lite",
  "rand",
  "reqwest",

Cargo.toml

@@ -22,14 +22,13 @@ clap            = { version = "4", features = [ "wrap_help", "cargo", "derive" ]
 crossbeam-queue = "0.3.1"
 crossbeam-utils = "0.8.1"
 dirs            = "4.0.0"
-fern            = "0.6.0"
 form_urlencoded = "1.0"
 futures         = "0.3.4"
 hyper           = { version = "0.14", features = [ "server", "stream" ] }
 listenfd        = "1"
 log             = "0.4.8"
-log-reroute     = "0.1.5"
 num_cpus        = "1.12.0"
+once_cell       = "1"
 pin-project-lite = "0.2.4"
 rand            = "0.8.1"
 reqwest         = { version = "0.11.0", default-features = false, features = ["blocking", "rustls-tls" ] }

doc/manual/source/manual-page.rst

@@ -1534,6 +1534,10 @@ SIGUSR1: Reload TALs and restart validation
    that succeeds, restart validation. If loading the TALs fails, Routinator
    will exit.
 
+SIGUSR2: Re-open log file
+   When receiving SIGUSR2 and logging to a file is enabled, Routinator will
+   re-open the log file. If this fails, Routinator will exit.
+
 Exit Status
 -----------
 

src/operation.rs

@@ -19,7 +19,7 @@ use std::str::FromStr;
 use std::sync::mpsc;
 use std::sync::Arc;
 use std::sync::mpsc::RecvTimeoutError;
-use std::time::Duration;
+use std::time::{Duration, Instant};
 #[cfg(feature = "rta")] use bytes::Bytes;
 use clap::{Arg, Args, ArgAction, ArgMatches, FromArgMatches, Parser};
 use log::{error, info};
@@ -275,25 +275,46 @@ impl Server {
                 if let Some(log) = log.as_ref() {
                     log.flush();
                 }
-                match sig_rx.recv_timeout(timeout) {
-                    Ok(UserSignal::ReloadTals) => {
-                        match validation.reload_tals() {
-                            Ok(_) => {
-                                info!("Reloaded TALs at user request.");
-                            },
-                            Err(_) => {
-                                error!(
-                                    "Fatal: Reloading TALs failed, \
-                                     shutting down."
-                                );
-                                break Err(Failed);
+
+                // Because we don’t want to restart validation upon
+                // log rotation, we need to loop here. But then we need
+                // to recalculate timeout.
+                let deadline = Instant::now() + timeout;
+                let end = loop {
+                    let timeout = deadline.saturating_duration_since(
+                        Instant::now()
+                    );
+                    match sig_rx.recv_timeout(timeout) {
+                        Ok(UserSignal::ReloadTals) => {
+                            match validation.reload_tals() {
+                                Ok(_) => {
+                                    info!("Reloaded TALs at user request.");
+                                    break None;
+                                },
+                                Err(_) => {
+                                    error!(
+                                        "Fatal: Reloading TALs failed, \
+                                         shutting down."
+                                    );
+                                    break Some(Err(Failed));
+                                }
                             }
                         }
+                        Ok(UserSignal::RotateLog) => {
+                            if process.rotate_log().is_err() {
+                                break Some(Err(Failed));
+                            }
+                        }
+                        Err(RecvTimeoutError::Timeout) => {
+                            break None;
+                        }
+                        Err(RecvTimeoutError::Disconnected) => {
+                            break Some(Ok(()));
+                        }
                     }
-                    Err(RecvTimeoutError::Timeout) => { }
-                    Err(RecvTimeoutError::Disconnected) => {
-                        break Ok(());
-                    }
+                };
+                if let Some(end) = end {
+                    break end;
                 }
             };
             // An error here means the receiver is gone which is fine.
@@ -1219,6 +1240,7 @@ impl Man {
 #[allow(dead_code)]
 enum UserSignal {
     ReloadTals,
+    RotateLog,
 }
 
 /// Wait for the next validation run or a user telling us to quit or reload.
@@ -1227,6 +1249,7 @@ enum UserSignal {
 #[cfg(unix)]
 struct SignalListener {
     usr1: Signal,
+    usr2: Signal,
 }
 
 #[cfg(unix)]
@@ -1239,7 +1262,14 @@ impl SignalListener {
                     error!("Attaching to signal USR1 failed: {}", err);
                     return Err(Failed)
                 }
-            }
+            },
+            usr2: match signal(SignalKind::user_defined2()) {
+                Ok(usr2) => usr2,
+                Err(err) => {
+                    error!("Attaching to signal USR2 failed: {}", err);
+                    return Err(Failed)
+                }
+            },
         })
     }
 
@@ -1247,8 +1277,10 @@ impl SignalListener {
     ///
     /// Returns what to do.
     pub async fn next(&mut self) -> UserSignal {
-        self.usr1.recv().await;
-        UserSignal::ReloadTals
+        tokio::select! {
+            _ = self.usr1.recv() => UserSignal::ReloadTals,
+            _ = self.usr2.recv() => UserSignal::RotateLog,
+        }
     }
 }
 

src/process.rs

@@ -1,16 +1,21 @@
 //! Managing the process Routinator runs in.
 
-use std::{fs, io};
+use std::{fs, io, mem, process};
 use std::future::Future;
+use std::io::Write;
 use std::net::TcpListener;
-use std::path::Path;
-use std::sync::mpsc;
+use std::ops::{Deref, DerefMut};
+use std::path::PathBuf;
+use std::sync::Arc;
 use bytes::Bytes;
-use chrono::{DateTime, Utc};
+use chrono::Utc;
 use log::{error, LevelFilter};
+use once_cell::sync::OnceCell;
 use tokio::runtime::Runtime;
 use crate::config::{Config, LogTarget};
 use crate::error::Failed;
+use crate::utils::date::{format_iso_date, format_local_iso_date};
+use crate::utils::fmt::WriteOrPanic;
 use crate::utils::sync::{Mutex, RwLock};
 
 
@@ -58,22 +63,17 @@ impl Process {
     /// Initialize logging.
     ///
     /// All diagnostic output of Routinator is done via logging, never to
-    /// stderr directly. Thus, it is important to initalize logging before
+    /// stderr directly. Thus, it is important to initialize logging before
     /// doing anything else that may result in such output. This function
     /// does exactly that. It sets a maximum log level of `warn`, leading
     /// only printing important information, and directs all logging to
     /// stderr.
     fn init_logging() -> Result<(), Failed> {
         log::set_max_level(LevelFilter::Warn);
-        if let Err(err) = log_reroute::init() {
+        if let Err(err) = log::set_logger(&GLOBAL_LOGGER) {
             eprintln!("Failed to initialize logger: {}.\nAborting.", err);
             return Err(Failed)
-        };
-        let dispatch = fern::Dispatch::new()
-            .level(LevelFilter::Error)
-            .chain(io::stderr())
-            .into_log().1;
-        log_reroute::reroute_boxed(dispatch);
+        }
         Ok(())
     }
 
@@ -87,133 +87,22 @@ impl Process {
         daemon: bool,
         with_output: bool
     ) -> Result<Option<LogOutput>, Failed> {
-        let logger = match self.config.log_target {
-            #[cfg(unix)]
-            LogTarget::Default(fac) => {
-                if daemon {
-                    self.syslog_logger(fac)?
-                }
-                else {
-                    self.stderr_logger(false)
-                }
-            }
-            #[cfg(unix)]
-            LogTarget::Syslog(fac) => {
-                self.syslog_logger(fac)?
-            }
-            LogTarget::Stderr => {
-                self.stderr_logger(daemon)
-            }
-            LogTarget::File(ref path) => {
-                self.file_logger(path)?
-            }
-        };
-        let (logger, res) = if with_output {
-            let (tx, res) = LogOutput::new();
-            let logger = logger.chain(tx);
-            (logger, Some(res))
+        let (output, res) = if with_output {
+            let output = LogOutput::new();
+            (Some(output.0), Some(output.1))
         }
         else {
-            (logger, None)
+            (None, None)
         };
-
-        log_reroute::reroute_boxed(logger.into_log().1);
+        let logger = Logger::new(&self.config, daemon, output)?;
+        GLOBAL_LOGGER.switch(logger);
         log::set_max_level(self.config.log_level);
         Ok(res)
     }
 
-    /// Creates a syslog logger and configures correctly.
-    #[cfg(unix)]
-    fn syslog_logger(
-        &self,
-        facility: syslog::Facility
-    ) -> Result<fern::Dispatch, Failed> {
-        let process = std::env::current_exe().ok().and_then(|path|
-            path.file_name()
-                .and_then(std::ffi::OsStr::to_str)
-                .map(ToString::to_string)
-        ).unwrap_or_else(|| String::from("routinator"));
-        let formatter = syslog::Formatter3164 {
-            facility,
-            hostname: None,
-            process,
-            pid: std::process::id(),
-        };
-        let logger = syslog::unix(formatter.clone()).or_else(|_| {
-            syslog::tcp(formatter.clone(), ("127.0.0.1", 601))
-        }).or_else(|_| {
-            syslog::udp(formatter, ("127.0.0.1", 0), ("127.0.0.1", 514))
-        });
-        match logger {
-            Ok(logger) => {
-                Ok(self.fern_logger(false).chain(
-                    Box::new(syslog::BasicLogger::new(logger))
-                    as Box::<dyn log::Log>
-                ))
-            }
-            Err(err) => {
-                error!("Cannot connect to syslog: {}", err);
-                Err(Failed)
-            }
-        }
-    }
-
-    /// Creates a stderr logger.
-    ///
-    /// If we are in daemon mode, we add a timestamp to the output.
-    fn stderr_logger(&self, daemon: bool) -> fern::Dispatch {
-        self.fern_logger(daemon).chain(io::stderr())
-    }
-
-    /// Creates a file logger using the file provided by `path`.
-    fn file_logger(&self, path: &Path) -> Result<fern::Dispatch, Failed> {
-        let file = match fern::log_file(path) {
-            Ok(file) => file,
-            Err(err) => {
-                error!(
-                    "Failed to open log file '{}': {}",
-                    path.display(), err
-                );
-                return Err(Failed)
-            }
-        };
-        Ok(self.fern_logger(true).chain(file))
-    }
-
-    /// Creates and returns a fern logger.
-    fn fern_logger(&self, timestamp: bool) -> fern::Dispatch {
-        let mut res = fern::Dispatch::new();
-        if timestamp {
-            res = res.format(|out, message, record| {
-                out.finish(format_args!(
-                    "{} [{}] {}",
-                    chrono::Local::now().format("[%Y-%m-%d %H:%M:%S]"),
-                    record.level(),
-                    message
-                ))
-            });
-        }
-        else {
-            res = res.format(|out, message, record| {
-                out.finish(format_args!(
-                    "[{}] {}",
-                    record.level(),
-                    message
-                ))
-            });
-        }
-        res = res
-            .level(self.config.log_level)
-            .level_for("rustls", LevelFilter::Error);
-        if self.config.log_level == LevelFilter::Debug {
-            res = res
-                .level_for("tokio_reactor", LevelFilter::Info)
-                .level_for("hyper", LevelFilter::Info)
-                .level_for("reqwest", LevelFilter::Info)
-                .level_for("h2", LevelFilter::Info)
-                .level_for("sled", LevelFilter::Info);
-        }
-        res
+    /// Rotates the log file if necessary.
+    pub fn rotate_log(&self) -> Result<(), Failed> {
+        GLOBAL_LOGGER.rotate()
     }
 }
 
@@ -310,46 +199,417 @@ impl Process {
 }
 
 
+//------------ Logger --------------------------------------------------------
+
+/// Format and write log messages.
+struct Logger {
+    /// Where to write messages to.
+    target: Mutex<LogBackend>,
+
+    /// An additional target for showing the log in the HTTP server.
+    output: Option<Arc<Mutex<String>>>,
+
+    /// The maximum log level.
+    log_level: log::LevelFilter,
+}
+
+/// The actual target for logging
+enum LogBackend {
+    #[cfg(unix)]
+    Syslog(SyslogLogger),
+    File {
+        file: fs::File,
+        path: PathBuf,
+    },
+    Stderr {
+        stderr: io::Stderr,
+        timestamp: bool,
+    }
+}
+
+impl Logger {
+    /// Creates a new logger from config and additional information.
+    fn new(
+        config: &Config, daemon: bool, output: Option<Arc<Mutex<String>>>
+    ) -> Result<Self, Failed> {
+        let target = match config.log_target {
+            #[cfg(unix)]
+            LogTarget::Default(facility) => {
+                if daemon { 
+                    Self::new_syslog_target(facility)?
+                }
+                else {
+                    Self::new_stderr_target(false)
+                }
+            }
+            #[cfg(unix)]
+            LogTarget::Syslog(facility) => {
+                Self::new_syslog_target(facility)?
+            }
+            LogTarget::File(ref path) => {
+                Self::new_file_target(path.clone())?
+            }
+            LogTarget::Stderr => {
+                Self::new_stderr_target(daemon)
+            }
+        };
+        Ok(Self {
+            target: Mutex::new(target),
+            output,
+            log_level: config.log_level,
+        })
+    }
+
+    /// Creates a syslog target.
+    #[cfg(unix)]
+    fn new_syslog_target(
+        facility: syslog::Facility
+    ) -> Result<LogBackend, Failed> {
+        SyslogLogger::new(facility).map(LogBackend::Syslog)
+    }
+
+    fn new_file_target(path: PathBuf) -> Result<LogBackend, Failed> {
+        Ok(LogBackend::File {
+            file: match Self::open_log_file(&path) {
+                Ok(file) => file,
+                Err(err) => {
+                    error!(
+                        "Failed to open log file '{}': {}",
+                        path.display(), err
+                    );
+                    return Err(Failed)
+                }
+            },
+            path
+        })
+    }
+
+    /// Opens a log file.
+    fn open_log_file(path: &PathBuf) -> Result<fs::File, io::Error> {
+        fs::OpenOptions::new().create(true).append(true).open(path)
+    }
+
+    /// Configures the stderr target.
+    fn new_stderr_target(timestamp: bool) -> LogBackend {
+        LogBackend::Stderr {
+            stderr: io::stderr(),
+            timestamp,
+        }
+    }
+
+    /// Logs a message.
+    ///
+    /// This method may exit the whole process if logging fails.
+    fn log(&self, record: &log::Record) {
+        if self.should_ignore(record) {
+            return;
+        }
+
+        if let Some(output) = self.output.as_ref() {
+            writeln!(output.lock(), "{}", record.args());
+        }
+
+        if let Err(err) = self.try_log(record) {
+            self.log_failure(err);
+        }
+    }
+
+    /// Tries logging a message and returns an error if there is one.
+    fn try_log(&self, record: &log::Record) -> Result<(), io::Error> {
+        match self.target.lock().deref_mut() {
+            #[cfg(unix)]
+            LogBackend::Syslog(ref mut logger) => logger.log(record),
+            LogBackend::File { ref mut file, .. } => {
+                writeln!(
+                    file, "[{}] [{}] {}",
+                    format_local_iso_date(chrono::Local::now()),
+                    record.level(),
+                    record.args()
+                )
+            }
+            LogBackend::Stderr{ ref mut stderr, timestamp } => {
+                // We never fail when writing to stderr.
+                if *timestamp {
+                    let _ = write!(stderr, "[{}] ",
+                        format_local_iso_date(chrono::Local::now()),
+                    );
+                }
+                let _ = writeln!(
+                    stderr, "[{}] {}", record.level(), record.args()
+                );
+                Ok(())
+            }
+        }
+    }
+
+    /// Handles an error that happened during logging.
+    fn log_failure(&self, err: io::Error) -> ! {
+        // We try to write a meaningful message to stderr and then abort.
+        match self.target.lock().deref() {
+            #[cfg(unix)]
+            LogBackend::Syslog(_) => {
+                eprintln!("Logging to syslog failed: {}. Exiting.", err);
+            }
+            LogBackend::File { ref path, .. } => {
+                eprintln!(
+                    "Logging to file {} failed: {}. Exiting.",
+                    path.display(),
+                    err
+                );
+            }
+            LogBackend::Stderr { ..  } => {
+                // We never fail when writing to stderr.
+            }
+        }
+        process::exit(1)
+    }
+
+    /// Flushes the logging backend.
+    fn flush(&self) {
+        match self.target.lock().deref_mut() {
+            #[cfg(unix)]
+            LogBackend::Syslog(ref mut logger) => logger.flush(),
+            LogBackend::File { ref mut file, .. } => {
+                let _ = file.flush();
+            }
+            LogBackend::Stderr { ref mut stderr, .. } => {
+                let _  = stderr.lock().flush();
+            }
+        }
+    }
+
+    /// Determines whether a log record should be ignored.
+    ///
+    /// This filters out messages by libraries that we don’t really want to
+    /// see.
+    fn should_ignore(&self, record: &log::Record) -> bool {
+        let module = match record.module_path() {
+            Some(module) => module,
+            None => return false,
+        };
+
+        // log::Level sorts more important first.
+
+        if record.level() > log::Level::Error {
+            // From rustls, only log errors.
+            if module.starts_with("rustls") {
+                return true
+            }
+        }
+        if self.log_level >= log::LevelFilter::Debug {
+            // Don’t filter anything else if we are in debug or trace.
+            return false
+        }
+
+        // Ignore these modules unless INFO or more important.
+        record.level() > log::Level::Info && (
+               module.starts_with("tokio_reactor")
+            || module.starts_with("hyper")
+            || module.starts_with("reqwest")
+            || module.starts_with("h2")
+        )
+    }
+
+    /// Rotates the log target if necessary.
+    ///
+    /// This method exits the whole process when rotating fails.
+    fn rotate(&self) -> Result<(), Failed> {
+        if let LogBackend::File {
+            ref mut file, ref path
+        } = self.target.lock().deref_mut() {
+            // This tries to open the file. If this fails, it writes a
+            // message to both the old file and stderr and then exits.
+            *file = match Self::open_log_file(path) {
+                Ok(file) => file,
+                Err(err) => {
+                    let _ = writeln!(file,
+                        "Re-opening log file {} failed: {}. Exiting.",
+                        path.display(), err
+                    );
+                    eprintln!(
+                        "Re-opening log file {} failed: {}. Exiting.",
+                        path.display(), err
+                    );
+                    return Err(Failed)
+                }
+            }
+        }
+        Ok(())
+    }
+}
+
+
+//------------ SyslogLogger --------------------------------------------------
+
+/// A syslog logger.
+///
+/// This is essentially [`syslog::BasicLogger`] but that one keeps the logger
+/// behind a mutex – which we already do – and doesn’t return error – which
+/// we do want to see.
+#[cfg(unix)]
+struct SyslogLogger(
+    syslog::Logger<syslog::LoggerBackend, syslog::Formatter3164>
+);
+
+#[cfg(unix)]
+impl SyslogLogger {
+    /// Creates a new syslog logger.
+    fn new(facility: syslog::Facility) -> Result<Self, Failed> {
+        let process = std::env::current_exe().ok().and_then(|path|
+            path.file_name()
+                .and_then(std::ffi::OsStr::to_str)
+                .map(ToString::to_string)
+        ).unwrap_or_else(|| String::from("routinator"));
+        let formatter = syslog::Formatter3164 {
+            facility,
+            hostname: None,
+            process,
+            pid: std::process::id(),
+        };
+        let logger = syslog::unix(formatter.clone()).or_else(|_| {
+            syslog::tcp(formatter.clone(), ("127.0.0.1", 601))
+        }).or_else(|_| {
+            syslog::udp(formatter, ("127.0.0.1", 0), ("127.0.0.1", 514))
+        });
+        match logger {
+            Ok(logger) => Ok(Self(logger)),
+            Err(err) => {
+                error!("Cannot connect to syslog: {}", err);
+                Err(Failed)
+            }
+        }
+    }
+
+    /// Tries logging.
+    fn log(&mut self, record: &log::Record) -> Result<(), io::Error> {
+        match record.level() {
+            log::Level::Error => self.0.err(record.args()),
+            log::Level::Warn => self.0.warning(record.args()),
+            log::Level::Info => self.0.info(record.args()),
+            log::Level::Debug => self.0.debug(record.args()),
+            log::Level::Trace => {
+                // Syslog doesn’t have trace, use debug instead.
+                self.0.debug(record.args())
+            }
+        }.map_err(|err| {
+            match err.0 {
+                syslog::ErrorKind::Io(err) => err,
+                syslog::ErrorKind::Msg(err) => {
+                    io::Error::new(io::ErrorKind::Other, err)
+                }
+                err => {
+                    io::Error::new(io::ErrorKind::Other, format!("{}", err))
+                }
+            }
+        })
+    }
+
+    /// Flushes the logger.
+    ///
+    /// Ignores any errors.
+    fn flush(&mut self) {
+        let _ = self.0.backend.flush();
+    }
+}
+
+
+//------------ GlobalLogger --------------------------------------------------
+
+/// The global logger.
+///
+/// A value of this type can go into a static. Until a proper logger is
+/// installed, it just writes all log output to stderr.
+struct GlobalLogger {
+    /// The real logger. Can only be set once.
+    inner: OnceCell<Logger>,
+}
+
+/// The static for the log crate.
+static GLOBAL_LOGGER: GlobalLogger = GlobalLogger::new();
+
+impl GlobalLogger {
+    /// Creates a new provisional logger.
+    const fn new() -> Self {
+        GlobalLogger { inner: OnceCell::new() }
+    }
+
+    /// Switches to the proper logger.
+    fn switch(&self, logger: Logger) {
+        if self.inner.set(logger).is_err() {
+            panic!("Tried to switch logger more than once.")
+        }
+    }
+
+    /// Performs a log rotation.
+    fn rotate(&self) -> Result<(), Failed> {
+        match self.inner.get() {
+            Some(logger) => logger.rotate(),
+            None => Ok(()),
+        }
+    }
+}
+
+
+impl log::Log for GlobalLogger {
+    fn enabled(&self, _: &log::Metadata<'_>) -> bool {
+        true
+    }
+
+    fn log(&self, record: &log::Record<'_>) {
+        match self.inner.get() {
+            Some(logger) => logger.log(record),
+            None => {
+                let _ = writeln!(
+                    io::stderr().lock(), "[{}] {}",
+                    record.level(), record.args()
+                );
+            }
+        }
+    }
+
+    fn flush(&self) {
+        if let Some(logger) = self.inner.get() {
+            logger.flush()
+        }
+    }
+}
+
+
 //------------ LogOutput -----------------------------------------------------
 
 #[derive(Debug)]
 pub struct LogOutput {
-    queue: Mutex<mpsc::Receiver<String>>,
-    current: RwLock<(Bytes, DateTime<Utc>)>,
+    queue: Arc<Mutex<String>>,
+    current: RwLock<Bytes>,
 }
 
 impl LogOutput {
-    fn new() -> (mpsc::Sender<String>, Self) {
-        let (tx, rx) = mpsc::channel();
+    fn new() -> (Arc<Mutex<String>>, Self) {
+        let queue = Arc::new(Mutex::new(String::new()));
         let res = LogOutput {
-            queue: Mutex::new(rx),
-            current: RwLock::new((
+            queue: queue.clone(),
+            current: RwLock::new(
                 "Initial validation ongoing. Please wait.".into(),
-                Utc::now()
-            ))
+            )
         };
-        (tx, res)
+        (queue, res)
     }
 
     pub fn start(&self) {
-        self.current.write().1 = Utc::now();
+        let new_string = format!(
+            "Log from validation run started at {}\n\n",
+            format_iso_date(Utc::now())
+        );
+        let _ = mem::replace(self.queue.lock().deref_mut(), new_string);
     }
 
     pub fn flush(&self) {
-        let queue = self.queue.lock();
-        let started = self.current.read().1;
-
-        let mut content = format!(
-            "Log from validation run started at {}\n\n", started
-        );
-        for item in queue.try_iter() {
-            content.push_str(&item)
-        }
-        self.current.write().0 = content.into();
+        let content = mem::take(self.queue.lock().deref_mut());
+        *self.current.write() = content.into();
     }
 
     pub fn get_output(&self) -> Bytes {
-        self.current.read().0.clone()
+        self.current.read().clone()
     }
 }
 

src/utils/date.rs

@@ -1,7 +1,7 @@
 //! Utilities for dealing with HTTP.
 
 use std::fmt;
-use chrono::{DateTime, Utc};
+use chrono::{DateTime, Local, Utc};
 use chrono::format::{Item, Fixed, Numeric, Pad};
 
 
@@ -104,23 +104,42 @@ pub fn format_http_date(date: DateTime<Utc>) -> String {
 
 //------------ Constructing ISO Dates ----------------------------------------
 
-const ISO_DATE: &[Item<'static>] = &[
-    Item::Numeric(Numeric::Year, Pad::Zero),
-    Item::Literal("-"),
-    Item::Numeric(Numeric::Month, Pad::Zero),
-    Item::Literal("-"),
-    Item::Numeric(Numeric::Day, Pad::Zero),
-    Item::Literal("T"),
-    Item::Numeric(Numeric::Hour, Pad::Zero),
-    Item::Literal(":"),
-    Item::Numeric(Numeric::Minute, Pad::Zero),
-    Item::Literal(":"),
-    Item::Numeric(Numeric::Second, Pad::Zero),
-    Item::Literal("Z"),
-];
 
 pub fn format_iso_date(date: DateTime<Utc>) -> impl fmt::Display {
-    date.format_with_items(ISO_DATE.iter())
+    const UTC_ISO_DATE: &[Item<'static>] = &[
+        Item::Numeric(Numeric::Year, Pad::Zero),
+        Item::Literal("-"),
+        Item::Numeric(Numeric::Month, Pad::Zero),
+        Item::Literal("-"),
+        Item::Numeric(Numeric::Day, Pad::Zero),
+        Item::Literal("T"),
+        Item::Numeric(Numeric::Hour, Pad::Zero),
+        Item::Literal(":"),
+        Item::Numeric(Numeric::Minute, Pad::Zero),
+        Item::Literal(":"),
+        Item::Numeric(Numeric::Second, Pad::Zero),
+        Item::Literal("Z"),
+    ];
+
+    date.format_with_items(UTC_ISO_DATE.iter())
+}
+
+pub fn format_local_iso_date(date: DateTime<Local>) -> impl fmt::Display {
+    const LOCAL_ISO_DATE: &[Item<'static>] = &[
+        Item::Numeric(Numeric::Year, Pad::Zero),
+        Item::Literal("-"),
+        Item::Numeric(Numeric::Month, Pad::Zero),
+        Item::Literal("-"),
+        Item::Numeric(Numeric::Day, Pad::Zero),
+        Item::Literal("T"),
+        Item::Numeric(Numeric::Hour, Pad::Zero),
+        Item::Literal(":"),
+        Item::Numeric(Numeric::Minute, Pad::Zero),
+        Item::Literal(":"),
+        Item::Numeric(Numeric::Second, Pad::Zero),
+    ];
+
+    date.format_with_items(LOCAL_ISO_DATE.iter())
 }