logging: use tracing instead of custom logging code

Cargo.lock

@@ -306,6 +306,8 @@ dependencies = [
  "tempfile",
  "test_bin",
  "tokio",
+ "tracing",
+ "tracing-subscriber",
 ]
 
 [[package]]
@@ -1156,9 +1158,9 @@ dependencies = [
 
 [[package]]
 name = "tracing"
-version = "0.1.40"
+version = "0.1.41"
 source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "c3523ab5a71916ccf420eebdf5521fcef02141234bbc0b8a49f2fdc4544364ef"
+checksum = "784e0ac535deb450455cbfa28a6f0df145ea1bb7ae51b821cf5e7927fdcfbdd0"
 dependencies = [
  "log",
  "pin-project-lite",
@@ -1168,9 +1170,9 @@ dependencies = [
 
 [[package]]
 name = "tracing-attributes"
-version = "0.1.27"
+version = "0.1.28"
 source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "34704c8d6ebcbc939824180af020566b01a7c01f80641264eba0999f6c2b6be7"
+checksum = "395ae124c09f9e6918a2310af6038fba074bcf474ac352496d5910dd59a2226d"
 dependencies = [
  "proc-macro2",
  "quote",
@@ -1179,9 +1181,9 @@ dependencies = [
 
 [[package]]
 name = "tracing-core"
-version = "0.1.32"
+version = "0.1.33"
 source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "c06d3da6113f116aaee68e4d601191614c9053067f9ab7f6edbcb161237daa54"
+checksum = "e672c95779cf947c5311f83787af4fa8fffd12fb27e4993211a84bdfd9610f9c"
 dependencies = [
  "once_cell",
  "valuable",
@@ -1200,9 +1202,9 @@ dependencies = [
 
 [[package]]
 name = "tracing-subscriber"
-version = "0.3.18"
+version = "0.3.19"
 source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "ad0f048c97dbd9faa9b7df56362b8ebcaa52adb06b498c050d2f4e32f90a7a8b"
+checksum = "e8189decb5ac0fa7bc8b96b7cb9b2701d60d48805aca84a238004d665fcc4008"
 dependencies = [
  "matchers",
  "nu-ansi-term",

Cargo.toml

@@ -45,6 +45,8 @@ tokio = "1.40.0"
 # still uses it. And sharded-slab is used by tracing-subscriber, which is
 # used by domain, which is used by us.
 _unused_lazy_static = { package = "lazy_static", version = "1.0.2" }
+tracing = "0.1.41"
+tracing-subscriber = "0.3.19"
 
 [dev-dependencies]
 test_bin = "0.4.0"

src/commands/notify.rs

@@ -10,10 +10,10 @@ use domain::rdata::Soa;
 use domain::tsig::Key;
 use domain::utils::base16;
 use lexopt::Arg;
+use tracing::warn;
 
 use crate::env::Env;
 use crate::error::Error;
-use crate::log::warning;
 use crate::parse::TSigInfo;
 use crate::Args;
 
@@ -224,20 +224,17 @@ impl Notify {
             }
 
             let Ok(name) = Name::<Vec<u8>>::from_str(server) else {
-                warning!(env, "invalid domain name \"{server}\", skipping.");
+                warn!("invalid domain name \"{server}\", skipping.");
                 continue;
             };
 
             let Ok(hosts) = resolver.lookup_host(&name).await else {
-                warning!(env, "could not resolve host \"{name}\", skipping.");
+                warn!("could not resolve host \"{name}\", skipping.");
                 continue;
             };
 
             if hosts.is_empty() {
-                warning!(
-                    env,
-                    "skipping bad address: {name}: Name or service not known"
-                );
+                warn!("skipping bad address: {name}: Name or service not known");
                 continue;
             }
 
@@ -582,4 +579,23 @@ mod tests {
         assert_eq!(res.exit_code, 0);
         assert!(res.stderr.contains("Name or service not known"));
     }
+
+    #[test]
+    fn invalid_domain_name() {
+        let rpl = format!(
+            "
+            CONFIG_END
+
+            SCENARIO_BEGIN
+
+            SCENARIO_END
+        "
+        );
+
+        let cmd = FakeCmd::new(["dnst", "notify", "-z", "nlnetlabs.test", ""])
+            .stelline(rpl.as_bytes(), "notify.rpl");
+
+        let res = cmd.run();
+        assert!(res.stderr.contains("invalid domain name"));
+    }
 }

src/env/fake.rs

@@ -60,16 +60,16 @@ impl Env for FakeEnv {
         self.cmd.cmd.iter().map(Into::into)
     }
 
-    fn stdout(&self) -> Stream<impl fmt::Write> {
+    fn stdout(&self) -> Stream<impl io::Write> {
         Stream {
-            writer: self.stdout.clone(),
+            writer: Mutex::new(self.stdout.clone()),
             is_terminal: false,
         }
     }
 
-    fn stderr(&self) -> Stream<impl fmt::Write> {
+    fn stderr(&self) -> Stream<impl io::Write + Send + Sync + 'static> {
         Stream {
-            writer: self.stderr.clone(),
+            writer: Mutex::new(self.stderr.clone()),
             is_terminal: false,
         }
     }
@@ -192,27 +192,32 @@ impl FakeCmd {
 
 impl FakeEnv {
     pub fn get_stdout(&self) -> String {
-        self.stdout.0.lock().unwrap().clone()
+        String::from_utf8(self.stdout.0.lock().unwrap().clone()).unwrap()
     }
 
     pub fn get_stderr(&self) -> String {
-        self.stderr.0.lock().unwrap().clone()
+        String::from_utf8(self.stderr.0.lock().unwrap().clone()).unwrap()
     }
 }
 
 /// A type to used to mock stdout and stderr
 #[derive(Clone, Default)]
-pub struct FakeStream(Arc<Mutex<String>>);
+pub struct FakeStream(Arc<Mutex<Vec<u8>>>);
 
-impl fmt::Write for FakeStream {
-    fn write_str(&mut self, s: &str) -> fmt::Result {
-        self.0.lock().unwrap().push_str(s);
+impl io::Write for FakeStream {
+    fn write(&mut self, buf: &[u8]) -> io::Result<usize> {
+        self.0.lock().unwrap().extend_from_slice(buf);
+        Ok(buf.len())
+    }
+
+    fn flush(&mut self) -> io::Result<()> {
+        // do nothing
         Ok(())
     }
 }
 
 impl fmt::Display for FakeStream {
     fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
-        f.write_str(self.0.lock().unwrap().as_ref())
+        f.write_str(std::str::from_utf8(&self.0.lock().unwrap()).unwrap())
     }
 }

src/env/mod.rs

@@ -1,8 +1,10 @@
 use std::borrow::Cow;
 use std::ffi::OsString;
-use std::fmt;
 use std::net::SocketAddr;
+use std::ops::DerefMut;
 use std::path::Path;
+use std::sync::Mutex;
+use std::{fmt, io};
 
 mod real;
 
@@ -12,6 +14,7 @@ pub mod fake;
 use domain::net::client::protocol::{AsyncConnect, AsyncDgramRecv, AsyncDgramSend};
 use domain::resolv::{stub::conf::ResolvConf, StubResolver};
 pub use real::RealEnv;
+use tracing_subscriber::fmt::MakeWriter;
 
 pub trait Env {
     /// Get an iterator over the command line arguments passed to the program
@@ -22,12 +25,12 @@ pub trait Env {
     /// Get a reference to stdout
     ///
     /// Equivalent to [`std::io::stdout`]
-    fn stdout(&self) -> Stream<impl fmt::Write>;
+    fn stdout(&self) -> Stream<impl io::Write>;
 
     /// Get a reference to stderr
     ///
     /// Equivalent to [`std::io::stderr`]
-    fn stderr(&self) -> Stream<impl fmt::Write>;
+    fn stderr(&self) -> Stream<impl io::Write + Send + Sync + 'static>;
 
     // /// Get a reference to stdin
     // fn stdin(&self) -> impl io::Read;
@@ -59,19 +62,42 @@ pub trait Env {
 /// [`std::io::Write`]. Additionally, this `write_fmt` does not return a
 /// result. This means that we can use the [`write!`] and [`writeln`] macros
 /// without handling errors.
-pub struct Stream<T: fmt::Write> {
-    writer: T,
+pub struct Stream<T: io::Write> {
+    writer: Mutex<T>,
     is_terminal: bool,
 }
 
-impl<T: fmt::Write> Stream<T> {
+impl<'writer, T: io::Write + 'writer> MakeWriter<'writer> for Stream<T> {
+    type Writer = &'writer Self;
+
+    fn make_writer(&'writer self) -> Self::Writer {
+        &self
+    }
+}
+
+impl<T: io::Write> io::Write for &Stream<T> {
+    fn write(&mut self, buf: &[u8]) -> io::Result<usize> {
+        self.writer.lock().unwrap().deref_mut().write(buf)
+    }
+
+    fn flush(&mut self) -> io::Result<()> {
+        self.writer.lock().unwrap().deref_mut().flush()
+    }
+}
+
+impl<T: io::Write> Stream<T> {
     pub fn write_fmt(&mut self, args: fmt::Arguments<'_>) {
         // This unwrap is not _really_ safe, but we are using this as stdout.
         // The `println` macro also ignores errors and `push_str` of the
         // fake stream also does not return an error. If this fails, it means
         // we can't write to stdout anymore so a graceful exit will be very
         // hard anyway.
-        self.writer.write_fmt(args).unwrap();
+        self.writer
+            .lock()
+            .unwrap()
+            .deref_mut()
+            .write_fmt(args)
+            .unwrap();
     }
 
     pub fn is_terminal(&self) -> bool {
@@ -92,11 +118,11 @@ impl<E: Env> Env for &E {
         (**self).args_os()
     }
 
-    fn stdout(&self) -> Stream<impl fmt::Write> {
+    fn stdout(&self) -> Stream<impl io::Write> {
         (**self).stdout()
     }
 
-    fn stderr(&self) -> Stream<impl fmt::Write> {
+    fn stderr(&self) -> Stream<impl io::Write + Send + Sync + 'static> {
         (**self).stderr()
     }
 

src/env/real.rs

@@ -1,7 +1,7 @@
 use std::ffi::OsString;
-use std::fmt;
 use std::io::{self, IsTerminal};
 use std::path::Path;
+use std::sync::Mutex;
 
 use domain::net::client::protocol::{AsyncConnect, AsyncDgramRecv, AsyncDgramSend, UdpConnect};
 use domain::resolv::stub::conf::ResolvConf;
@@ -18,19 +18,19 @@ impl Env for RealEnv {
         std::env::args_os()
     }
 
-    fn stdout(&self) -> Stream<impl fmt::Write> {
+    fn stdout(&self) -> Stream<impl io::Write> {
         let stdout = io::stdout();
         Stream {
             is_terminal: stdout.is_terminal(),
-            writer: FmtWriter(io::stdout()),
+            writer: Mutex::new(stdout),
         }
     }
 
-    fn stderr(&self) -> Stream<impl fmt::Write> {
+    fn stderr(&self) -> Stream<impl io::Write + Send + Sync + 'static> {
         let stderr = io::stderr();
         Stream {
             is_terminal: stderr.is_terminal(),
-            writer: FmtWriter(io::stdout()),
+            writer: Mutex::new(stderr),
         }
     }
 
@@ -53,15 +53,3 @@ impl Env for RealEnv {
         StubResolver::from_conf(config)
     }
 }
-
-struct FmtWriter<T: io::Write>(T);
-
-impl<T: io::Write> fmt::Write for FmtWriter<T> {
-    fn write_str(&mut self, s: &str) -> std::fmt::Result {
-        self.0.write_all(s.as_bytes()).map_err(|_| fmt::Error)
-    }
-
-    fn write_fmt(&mut self, args: fmt::Arguments<'_>) -> fmt::Result {
-        self.0.write_fmt(args).map_err(|_| fmt::Error)
-    }
-}

src/error.rs

@@ -1,10 +1,10 @@
 use std::fmt;
-use std::{error, io};
+use std::io;
 
 use domain::base::wire::ParseError;
+use tracing::error;
 
 use crate::env::Env;
-use crate::log::error;
 
 //------------ Error ---------------------------------------------------------
 
@@ -58,8 +58,6 @@ impl Error {
 
     /// Pretty-print this error.
     pub fn pretty_print(&self, env: impl Env) {
-        let mut err = env.stderr();
-
         let msg = match &self.0.primary {
             // Clap errors are already styled. We don't want our own pretty
             // styling around that and context does not make sense for command
@@ -73,7 +71,8 @@ impl Error {
             PrimaryError::Other(error) => error,
         };
 
-        error!(env, "{msg}");
+        error!("{msg}");
+        let mut err = env.stderr();
         for context in &self.0.context {
             writeln!(err, "... while {context}");
         }
@@ -155,7 +154,7 @@ impl fmt::Debug for Error {
 
 //--- Error
 
-impl error::Error for Error {}
+impl std::error::Error for Error {}
 
 //------------ Macros --------------------------------------------------------
 

src/lib.rs

@@ -10,6 +10,7 @@ use commands::update::Update;
 use commands::LdnsCommand;
 use env::Env;
 use error::Error;
+use log::LogFormatter;
 
 pub use self::args::Args;
 
@@ -90,12 +91,23 @@ fn parse_args(env: impl Env) -> Result<Args, Error> {
 }
 
 pub fn run(env: impl Env) -> u8 {
-    let res = parse_args(&env).and_then(|args| args.execute(&env));
-    match res {
-        Ok(()) => 0,
-        Err(err) => {
-            err.pretty_print(&env);
-            err.exit_code()
+    let stderr = env.stderr();
+    let subscriber = tracing_subscriber::FmtSubscriber::builder()
+        .with_ansi(stderr.is_terminal())
+        .with_writer(stderr)
+        .event_format(LogFormatter {
+            program: env.args_os().next().unwrap().to_string_lossy().to_string(),
+        })
+        .finish();
+
+    tracing::subscriber::with_default(subscriber, || {
+        let res = parse_args(&env).and_then(|args| args.execute(&env));
+        match res {
+            Ok(()) => 0,
+            Err(err) => {
+                err.pretty_print(&env);
+                err.exit_code()
+            }
         }
-    }
+    })
 }

src/log.rs

@@ -1,54 +1,56 @@
-use std::fmt::Display;
+use std::fmt;
 
-use crate::env::Env;
+use tracing::{Event, Level, Subscriber};
+use tracing_subscriber::{
+    fmt::{format, FmtContext, FormatEvent, FormatFields},
+    registry::LookupSpan,
+};
 
 mod color {
-    pub const BLUE: u8 = 34;
-    pub const YELLOW: u8 = 33;
     pub const RED: u8 = 31;
+    pub const GREEN: u8 = 32;
+    pub const YELLOW: u8 = 33;
+    pub const BLUE: u8 = 34;
+    pub const PURPLE: u8 = 35;
 }
 
-#[derive(Clone, Copy, Debug, PartialEq, Eq)]
-pub enum LogLevel {
-    Info,
-    Warning,
-    Error,
+pub struct LogFormatter {
+    pub program: String,
 }
 
-impl LogLevel {
-    fn color(self) -> u8 {
-        match self {
-            Self::Info => color::BLUE,
-            Self::Warning => color::YELLOW,
-            Self::Error => color::RED,
+impl<S, N> FormatEvent<S, N> for LogFormatter
+where
+    S: Subscriber + for<'a> LookupSpan<'a>,
+    N: for<'a> FormatFields<'a> + 'static,
+{
+    fn format_event(
+        &self,
+        ctx: &FmtContext<'_, S, N>,
+        mut writer: format::Writer<'_>,
+        event: &Event<'_>,
+    ) -> fmt::Result {
+        // Format values from the event's's metadata:
+        let metadata = event.metadata();
+
+        write!(&mut writer, "[{}] ", &self.program)?;
+
+        let level = *metadata.level();
+        if writer.has_ansi_escapes() {
+            let color = match level {
+                Level::ERROR => color::RED,
+                Level::WARN => color::YELLOW,
+                Level::INFO => color::BLUE,
+                Level::DEBUG => color::GREEN,
+                Level::TRACE => color::PURPLE,
+            };
+            write!(&mut writer, "\x1B[{color}m{level}\x1B[0m: ",)?;
+        } else {
+            write!(&mut writer, "{level}: ")?;
         }
-    }
 
-    fn text(self) -> &'static str {
-        match self {
-            LogLevel::Info => "INFO",
-            LogLevel::Warning => "WARNING",
-            LogLevel::Error => "ERROR",
-        }
-    }
-}
-
-impl Display for LogLevel {
-    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
-        f.write_str(self.text())
-    }
-}
-
-struct Logger(&'static Env);
-
-pub fn log(env: impl Env, level: LogLevel, text: impl Display) {
-    let mut err = env.stderr();
-    let prog = std::env::args().next().unwrap();
-
-    if err.is_terminal() {
-        let color = level.color();
-        writeln!(err, "[{prog}] \x1B[{color}m{level}\x1B[0m: {text}");
-    } else {
-        writeln!(err, "[{prog}] {level}: {text}");
+        // Write fields on the event
+        ctx.field_format().format_fields(writer.by_ref(), event)?;
+
+        writeln!(writer)
     }
 }