fix: Simplify neqo_common::log and enforce clippy format checks

.clippy.toml

@@ -1,3 +1,4 @@
 disallowed-methods = [
     { path = "std::slice::from_raw_parts", reason = "see null_safe_slice" }
 ]
+allow-mixed-uninlined-format-args = false

neqo-bin/Cargo.toml

@@ -54,6 +54,9 @@ tokio = { version = "1", default-features = false, features = ["sync"] }
 bench = ["neqo-transport/bench"]
 draft-29 = []
 
+[package.metadata.cargo-machete]
+ignored = ["log"]
+
 [lib]
 # See https://github.com/bheisler/criterion.rs/blob/master/book/src/faq.md#cargo-bench-gives-unrecognized-option-errors-for-valid-command-line-options
 bench = false

neqo-bin/benches/main.rs

@@ -17,7 +17,6 @@ struct Benchmark {
 }
 
 fn transfer(c: &mut Criterion) {
-    neqo_common::log::init(Some(log::LevelFilter::Off));
     neqo_crypto::init_db(PathBuf::from_str("../test-fixture/db").unwrap()).unwrap();
 
     let done_sender = spawn_server();

neqo-bin/src/client/http09.rs

@@ -301,8 +301,7 @@ impl<'b> Handler<'b> {
                 qdebug!("READ[{stream_id}]: {} bytes", read_buffer.len());
             } else {
                 qdebug!(
-                    "READ[{}]: {}",
-                    stream_id,
+                    "READ[{stream_id}]: {}",
                     std::str::from_utf8(read_buffer).unwrap()
                 );
             }

neqo-bin/src/client/http3.rs

@@ -302,7 +302,7 @@ impl StreamHandler for DownloadStreamHandler {
         } else if let Ok(txt) = std::str::from_utf8(data) {
             qdebug!("READ[{stream_id}]: {txt}");
         } else {
-            qdebug!("READ[{}]: 0x{}", stream_id, hex(data));
+            qdebug!("READ[{stream_id}]: 0x{}", hex(data));
         }
 
         if fin {
@@ -344,7 +344,7 @@ impl StreamHandler for UploadStreamHandler {
                 qinfo!("Stream ID: {stream_id:?}, Upload time: {upload_time:?}");
             }
         } else {
-            panic!("Unexpected data [{}]: 0x{}", stream_id, hex(data));
+            panic!("Unexpected data [{stream_id}]: 0x{}", hex(data));
         }
         Ok(true)
     }

neqo-bin/src/client/mod.rs

@@ -463,7 +463,7 @@ impl<'a, H: Handler> Runner<'a, H> {
                     self.socket.send(&dgram)?;
                 }
                 Output::Callback(new_timeout) => {
-                    qdebug!("Setting timeout of {:?}", new_timeout);
+                    qdebug!("Setting timeout of {new_timeout:?}");
                     self.timeout = Some(Box::pin(tokio::time::sleep(new_timeout)));
                     break;
                 }
@@ -551,7 +551,7 @@ pub async fn client(mut args: Args) -> Res<()> {
 
     for ((host, port), mut urls) in urls_by_origin(&args.urls) {
         if args.resume && urls.len() < 2 {
-            qerror!("Resumption to {host} cannot work without at least 2 URLs.");
+            qerror!("Resumption to {host} cannot work without at least 2 URLs");
             exit(127);
         }
 
@@ -568,10 +568,8 @@ pub async fn client(mut args: Args) -> Res<()> {
         let mut socket = crate::udp::Socket::bind(local_addr_for(&remote_addr, 0))?;
         let real_local = socket.local_addr().unwrap();
         qinfo!(
-            "{} Client connecting: {:?} -> {:?}",
-            args.shared.alpn,
-            real_local,
-            remote_addr,
+            "{} Client connecting: {real_local:?} -> {remote_addr:?}",
+            args.shared.alpn
         );
 
         let hostname = format!("{host}");

neqo-bin/src/lib.rs

@@ -163,9 +163,8 @@ impl QuicParameters {
         assert_eq!(
             opt.is_some(),
             addr.is_some(),
-            "unable to resolve '{}' to an {} address",
+            "unable to resolve '{}' to an {v} address",
             opt.as_ref().unwrap(),
-            v,
         );
         addr
     }

neqo-bin/src/server/http09.rs

@@ -82,17 +82,17 @@ impl HttpServer {
         let url_dbg = String::from_utf8(partial.clone())
             .unwrap_or_else(|_| format!("<invalid UTF-8: {}>", hex(&partial)));
         if partial.len() < 4096 {
-            qdebug!("Saving partial URL: {}", url_dbg);
+            qdebug!("Saving partial URL: {url_dbg}");
             self.read_state.insert(stream_id, partial);
         } else {
-            qdebug!("Giving up on partial URL {}", url_dbg);
+            qdebug!("Giving up on partial URL {url_dbg}");
             conn.borrow_mut().stream_stop_sending(stream_id, 0).unwrap();
         }
     }
 
     fn stream_readable(&mut self, stream_id: StreamId, conn: &ConnectionRef) {
         if !stream_id.is_client_initiated() || !stream_id.is_bidi() {
-            qdebug!("Stream {} not client-initiated bidi, ignoring", stream_id);
+            qdebug!("Stream {stream_id} not client-initiated bidi, ignoring");
             return;
         }
         let (sz, fin) = conn

neqo-bin/src/server/mod.rs

@@ -252,7 +252,7 @@ impl ServerRunner {
                     socket.send(&dgram)?;
                 }
                 Output::Callback(new_timeout) => {
-                    qdebug!("Setting timeout of {:?}", new_timeout);
+                    qdebug!("Setting timeout of {new_timeout:?}");
                     *timeout = Some(Box::pin(tokio::time::sleep(new_timeout)));
                     break;
                 }
@@ -361,7 +361,7 @@ pub async fn server(mut args: Args) -> Res<()> {
                 args.shared.quic_parameters.quic_version = vec![Version::Version1];
             }
         } else {
-            qwarn!("Both -V and --qns-test were set. Ignoring testcase specific versions.");
+            qwarn!("Both -V and --qns-test were set. Ignoring testcase specific versions");
         }
 
         // These are the default for all tests except http3.

neqo-common/Cargo.toml

@@ -18,7 +18,7 @@ workspace = true
 [dependencies]
 # Checked against https://searchfox.org/mozilla-central/source/Cargo.lock 2024-11-11
 enum-map = { workspace = true }
-env_logger = { version = "0.10", default-features = false }
+env_logger = { version = "0.10", default-features = false, features = ["auto-color", "regex"] }
 hex = { version = "0.4", default-features = false, features = ["alloc"], optional = true }
 log = { workspace = true }
 qlog = { workspace = true }

neqo-common/src/log.rs

@@ -14,37 +14,6 @@ use std::{
 
 use env_logger::Builder;
 
-#[macro_export]
-macro_rules! do_log {
-    (target: $target:expr, $lvl:expr, $($arg:tt)+) => ({
-        let lvl = $lvl;
-        if lvl <= ::log::STATIC_MAX_LEVEL && lvl <= ::log::max_level() {
-            ::log::logger().log(
-                &::log::Record::builder()
-                    .args(format_args!($($arg)+))
-                    .level(lvl)
-                    .target($target)
-                    .module_path_static(Some(module_path!()))
-                    .file_static(Some(file!()))
-                    .line(Some(line!()))
-                    .build()
-            );
-        }
-    });
-    ($lvl:expr, $($arg:tt)+) => ($crate::do_log!(target: module_path!(), $lvl, $($arg)+))
-}
-
-#[macro_export]
-macro_rules! log_subject {
-    ($lvl:expr, $subject:expr) => {{
-        if $lvl <= ::log::max_level() {
-            format!("{}", $subject)
-        } else {
-            String::new()
-        }
-    }};
-}
-
 fn since_start() -> Duration {
     static START_TIME: OnceLock<Instant> = OnceLock::new();
     START_TIME.get_or_init(Instant::now).elapsed()
@@ -64,52 +33,71 @@ pub fn init(level_filter: Option<log::LevelFilter>) {
         }
         builder.format(|buf, record| {
             let elapsed = since_start();
+            let level_style = buf.default_level_style(record.level());
+            let mut bold = buf.style();
+            bold.set_bold(true);
             writeln!(
                 buf,
-                "{}s{:3}ms {} {}",
-                elapsed.as_secs(),
-                elapsed.as_millis() % 1000,
-                record.level(),
+                "{} {} {}",
+                bold.value(format!(
+                    "{}.{:03}",
+                    elapsed.as_secs(),
+                    elapsed.as_millis() % 1000
+                )),
+                level_style.value(record.level()),
                 record.args()
             )
         });
         if let Err(e) = builder.try_init() {
-            do_log!(::log::Level::Warn, "Logging initialization error {:?}", e);
+            eprintln!("Logging initialization error {e:?}");
         } else {
-            do_log!(::log::Level::Debug, "Logging initialized");
+            ::log::debug!("Logging initialized");
         }
     });
 }
 
 #[macro_export]
-macro_rules! log_invoke {
-    ($lvl:expr, $ctx:expr, $($arg:tt)*) => ( {
-        ::neqo_common::log::init(None);
-        ::neqo_common::do_log!($lvl, "[{}] {}", $ctx, format!($($arg)*));
-    } )
-}
-#[macro_export]
+// TODO: Enable `#[clippy::format_args]` once our MSRV is >= 1.84
 macro_rules! qerror {
-    ([$ctx:expr], $($arg:tt)*) => (::neqo_common::log_invoke!(::log::Level::Error, $ctx, $($arg)*););
-    ($($arg:tt)*) => ( { ::neqo_common::log::init(None); ::neqo_common::do_log!(::log::Level::Error, $($arg)*); } );
+    ($($arg:tt)*) => ( {
+        #[cfg(any(test, feature = "bench"))]
+        ::neqo_common::log::init(None);
+        ::log::error!($($arg)*);
+    } );
 }
 #[macro_export]
+// TODO: Enable `#[clippy::format_args]` once our MSRV is >= 1.84
 macro_rules! qwarn {
-    ([$ctx:expr], $($arg:tt)*) => (::neqo_common::log_invoke!(::log::Level::Warn, $ctx, $($arg)*););
-    ($($arg:tt)*) => ( { ::neqo_common::log::init(None); ::neqo_common::do_log!(::log::Level::Warn, $($arg)*); } );
+    ($($arg:tt)*) => ( {
+        #[cfg(any(test, feature = "bench"))]
+        ::neqo_common::log::init(None);
+        ::log::warn!($($arg)*);
+    } );
 }
 #[macro_export]
+// TODO: Enable `#[clippy::format_args]` once our MSRV is >= 1.84
 macro_rules! qinfo {
-    ([$ctx:expr], $($arg:tt)*) => (::neqo_common::log_invoke!(::log::Level::Info, $ctx, $($arg)*););
-    ($($arg:tt)*) => ( { ::neqo_common::log::init(None); ::neqo_common::do_log!(::log::Level::Info, $($arg)*); } );
+    ($($arg:tt)*) => ( {
+        #[cfg(any(test, feature = "bench"))]
+        ::neqo_common::log::init(None);
+        ::log::info!($($arg)*);
+    } );
 }
 #[macro_export]
+// TODO: Enable `#[clippy::format_args]` once our MSRV is >= 1.84
 macro_rules! qdebug {
-    ([$ctx:expr], $($arg:tt)*) => (::neqo_common::log_invoke!(::log::Level::Debug, $ctx, $($arg)*););
-    ($($arg:tt)*) => ( { ::neqo_common::log::init(None); ::neqo_common::do_log!(::log::Level::Debug, $($arg)*); } );
+    ($($arg:tt)*) => ( {
+        #[cfg(any(test, feature = "bench"))]
+        ::neqo_common::log::init(None);
+        ::log::debug!($($arg)*);
+    } );
 }
 #[macro_export]
+// TODO: Enable `#[clippy::format_args]` once our MSRV is >= 1.84
 macro_rules! qtrace {
-    ([$ctx:expr], $($arg:tt)*) => (::neqo_common::log_invoke!(::log::Level::Trace, $ctx, $($arg)*););
-    ($($arg:tt)*) => ( { ::neqo_common::log::init(None); ::neqo_common::do_log!(::log::Level::Trace, $($arg)*); } );
+    ($($arg:tt)*) => ( {
+        #[cfg(any(test, feature = "bench"))]
+        ::neqo_common::log::init(None);
+        ::log::trace!($($arg)*);
+    } );
 }

neqo-common/src/qlog.rs

@@ -149,11 +149,7 @@ impl NeqoQlog {
     {
         if let Some(inner) = self.inner.borrow_mut().as_mut() {
             if let Err(e) = f(&mut inner.streamer) {
-                crate::do_log!(
-                    ::log::Level::Error,
-                    "Qlog event generation failed with error {}; closing qlog.",
-                    e
-                );
+                log::error!("Qlog event generation failed with error {e}; closing qlog.");
                 *self.inner.borrow_mut() = None;
             }
         }
@@ -169,7 +165,7 @@ impl fmt::Debug for NeqoQlogShared {
 impl Drop for NeqoQlogShared {
     fn drop(&mut self) {
         if let Err(e) = self.streamer.finish_log() {
-            crate::do_log!(::log::Level::Error, "Error dropping NeqoQlog: {}", e);
+            log::error!("Error dropping NeqoQlog: {e}");
         }
     }
 }

neqo-common/tests/log.rs

@@ -19,40 +19,9 @@ fn basic() {
 fn args() {
     let num = 1;
     let obj = std::time::Instant::now();
-    qerror!("error {} {:?}", num, obj);
-    qwarn!("warn {} {:?}", num, obj);
-    qinfo!("info {} {:?}", num, obj);
-    qdebug!("debug {} {:?}", num, obj);
-    qtrace!("trace {} {:?}", num, obj);
-}
-
-#[test]
-fn context() {
-    let context = "context";
-    qerror!([context], "error");
-    qwarn!([context], "warn");
-    qinfo!([context], "info");
-    qdebug!([context], "debug");
-    qtrace!([context], "trace");
-}
-
-#[test]
-fn context_comma() {
-    let obj = vec![1, 2, 3];
-    let context = "context";
-    qerror!([context], "error {:?}", obj);
-    qwarn!([context], "warn {:?}", obj);
-    qinfo!([context], "info {:?}", obj);
-    qdebug!([context], "debug {:?}", obj);
-    qtrace!([context], "trace {:?}", obj);
-}
-
-#[test]
-fn context_expr() {
-    let context = vec![1, 2, 3];
-    qerror!([format!("{:x?}", context)], "error");
-    qwarn!([format!("{:x?}", context)], "warn");
-    qinfo!([format!("{:x?}", context)], "info");
-    qdebug!([format!("{:x?}", context)], "debug");
-    qtrace!([format!("{:x?}", context)], "trace");
+    qerror!("error {num} {obj:?}");
+    qwarn!("warn {num} {obj:?}");
+    qinfo!("info {num} {obj:?}");
+    qdebug!("debug {num} {obj:?}");
+    qtrace!("trace {num} {obj:?}");
 }