Improve logging.

`env_logger` is less flexible than `fern`, but it easily allows
filtering of log messages, such as mwalib which dumps a lot of traces.
`env_logger` is also better about handling colours/fancy symbols when
piping output.

Also improve a few of instances of trace logging. All vetoed and
unvetoed source names were being printed out on a single line, which
makes for an unpleasent terminal experience. Now these names are printed
out 5 at a time, which prints much faster. The units of a reported
separation were also incorrect.

CHANGELOG.md

@@ -34,6 +34,9 @@ Versioning](https://semver.org/spec/v2.0.0.html).
 - Bugs were fixed surrounding the reading of RTS solutions.
 
 ### Changed
+- The library used for logging has changed. The user experience should only be
+  superficial, but piping `hyperdrive` output to a file (e.g. a job output on a
+  supercomputer) should display a little better.
 - The output of `dipole-gains` is now less confusing.
 - When applying solutions, if a baseline/tile doesn't have an appropriate
   solution available, the output Jones matrix is all zeros. This is to avoid

Cargo.toml

@@ -64,8 +64,8 @@ clap = { version = "3.1.0", features = ["derive", "wrap_help"] }
 console = "0.15.0"
 crossbeam-channel = "0.5.0"
 crossbeam-utils = "0.8.7"
+env_logger = "0.9.1"
 erfa-sys = "0.2.0"
-fern = { version = "0.6.0", features = ["chrono", "colored"] }
 fitsio = "0.19.0"
 fitsio-sys = "0.4.0"
 flate2 = "1.0.13"

mdbook/src/defs/mwa/mwalib.md

@@ -4,6 +4,14 @@
 raw-data-reading library. `hyperdrive` users usually don't need to concern
 themselves with it, but `mwalib` errors may arise.
 
+`mwalib` can be quite noisy with log messages (particularly at the "trace"
+level); it is possible to suppress these messages by setting an environment
+variable:
+
+```
+RUST_LOG=mwalib=error
+```
+
 ## Errors
 
 ### Missing a key in the metafits file

src/bin/hyperdrive.rs

@@ -5,7 +5,6 @@
 //! The main hyperdrive binary.
 
 use clap::{AppSettings, Parser};
-use fern::colors::{Color, ColoredLevelConfig};
 use log::info;
 
 use mwa_hyperdrive::HyperdriveError;
@@ -290,70 +289,37 @@ fn cli() -> Result<(), HyperdriveError> {
     Ok(())
 }
 
-/// Activate a logger. Use colours only if we're on a tty (e.g. a terminal) and
-/// display source lines in log messages with verbosity >= 3.
-// This is pretty dirty code. Can it be cleaned up?
+/// Activate a logger. All log messages are put onto `stdout`. `env_logger`
+/// automatically only uses colours and fancy symbols if we're on a tty (e.g. a
+/// terminal); piped output will be formatted sensibly. Source code lines are
+/// displayed in log messages when verbosity >= 3.
 fn setup_logging(verbosity: u8) -> Result<(), log::SetLoggerError> {
-    let is_a_tty = is_a_tty();
-
-    let (high_level_messages, low_level_messages) = if is_a_tty {
-        let colours = ColoredLevelConfig::new()
-            .warn(Color::Red)
-            .info(Color::Green)
-            .debug(Color::Blue)
-            .trace(Color::Yellow);
-        let colours2 = colours;
-
-        (
-            fern::Dispatch::new().format(move |out, message, record| {
-                out.finish(format_args!(
-                    "{} {:<5} {}",
-                    chrono::Local::now().format("%Y-%m-%d %H:%M:%S"),
-                    colours.color(record.level()),
-                    message
-                ))
-            }),
-            fern::Dispatch::new().format(move |out, message, record| {
-                out.finish(format_args!(
-                    "{} {} line {:<3} {:<5} {}",
-                    chrono::Local::now().format("%Y-%m-%d %H:%M:%S"),
-                    record.target(),
-                    record.line().unwrap_or(0),
-                    colours2.color(record.level()),
-                    message
-                ))
-            }),
-        )
-    } else {
-        (
-            fern::Dispatch::new().format(move |out, message, record| {
-                out.finish(format_args!(
-                    "{} {:<5} {}",
-                    chrono::Local::now().format("%Y-%m-%d %H:%M:%S"),
-                    record.level(),
-                    message
-                ))
-            }),
-            fern::Dispatch::new().format(move |out, message, record| {
-                out.finish(format_args!(
-                    "{} {} line {:<3} {:<5} {}",
-                    chrono::Local::now().format("%Y-%m-%d %H:%M:%S"),
-                    record.target(),
-                    record.line().unwrap_or(0),
-                    record.level(),
-                    message
-                ))
-            }),
-        )
+    let mut builder = env_logger::Builder::from_default_env();
+    builder.target(env_logger::Target::Stdout);
+    builder.format_target(false);
+    match verbosity {
+        0 => builder.filter_level(log::LevelFilter::Info),
+        1 => builder.filter_level(log::LevelFilter::Debug),
+        2 => builder.filter_level(log::LevelFilter::Trace),
+        _ => {
+            builder.filter_level(log::LevelFilter::Trace);
+            builder.format(|buf, record| {
+                use std::io::Write;
+
+                // TODO: Add colours.
+                let timestamp = buf.timestamp();
+                let level = record.level();
+                let target = record.target();
+                let line = record.line().unwrap_or(0);
+                let message = record.args();
+
+                writeln!(buf, "[{timestamp} {level} {target}:{line}] {message}")
+            })
+        }
     };
+    builder.init();
 
-    let logger = match verbosity {
-        0 => high_level_messages.level(log::LevelFilter::Info),
-        1 => high_level_messages.level(log::LevelFilter::Debug),
-        2 => high_level_messages.level(log::LevelFilter::Trace),
-        _ => low_level_messages.level(log::LevelFilter::Trace),
-    };
-    logger.chain(std::io::stdout()).apply()
+    Ok(())
 }
 
 /// Write many info-level log lines of how this executable was compiled.
@@ -374,7 +340,3 @@ fn display_build_info() {
     info!("         with compiler {}", RUSTC_VERSION);
     info!("");
 }
-
-fn is_a_tty() -> bool {
-    atty::is(atty::Stream::Stdout) || atty::is(atty::Stream::Stderr)
-}

src/messages.rs

@@ -481,7 +481,20 @@ impl SkyModelDetails<'_> {
         if num_components > 10000 {
             warn!("Using more than 10,000 components!");
         }
-        trace!("Using sources: {:?}", self.source_list.keys());
+        if log::log_enabled!(log::Level::Trace) {
+            trace!("Using sources:");
+            let mut v = Vec::with_capacity(5);
+            for source in self.source_list.keys() {
+                if v.len() == 5 {
+                    trace!("  {v:?}");
+                    v.clear();
+                }
+                v.push(source);
+            }
+            if !v.is_empty() {
+                trace!("  {v:?}");
+            }
+        }
     }
 }
 

src/srclist/veto.rs

@@ -80,7 +80,7 @@ pub(crate) fn veto_sources(
                 let separation = comp.radec.separation(phase_centre);
                 if separation > dist_cutoff {
                     if log_enabled!(Trace) {
-                        trace!("A component (source {source_name}) was too far from the phase centre (separation {separation}°)");
+                        trace!("A component (source {source_name}) was too far from the phase centre (separation {}°)", separation.to_degrees());
                     }
                     return Either::Left(Ok(source_name));
                 }
@@ -166,11 +166,15 @@ pub(crate) fn veto_sources(
         "{} sources were vetoed from the source list",
         vetoed_sources.len()
     );
-    trace!(
-        "The following {} sources were vetoed from the source list: {:?}",
-        vetoed_sources.len(),
-        vetoed_sources
-    );
+    if log_enabled!(Trace) {
+        trace!(
+            "The following {} sources were vetoed from the source list:",
+            vetoed_sources.len()
+        );
+        for vetoed_sources in vetoed_sources.chunks(5) {
+            trace!("  {vetoed_sources:?}");
+        }
+    }
 
     // If there are fewer sources than requested after vetoing, we need to bail
     // out.