Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Open
wants to merge 10 commits into
base: main
Choose a base branch
from
Open

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

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
10 commits
Select commit Hold shift + click to select a range
161d22d
fix: Replace `neqo_common::log` with `log` crate
larseggert Dec 18, 2024
01319b6
Style the output a bit
larseggert Dec 18, 2024
0d43dea
Use variables in format strings where possible.
larseggert Dec 18, 2024
649e29a
Remove unneeded `format!` calls
larseggert Dec 18, 2024
1877d41
Fix bench
larseggert Dec 18, 2024
a65dce8
Retain `neqo-common::log`
larseggert Dec 18, 2024
69879bc
Minimize diff
larseggert Dec 18, 2024
ae0d462
machete
larseggert Dec 18, 2024
5ff2d82
Make `#[clippy::format_args]` a TODO :-(
larseggert Dec 18, 2024
8853788
Merge branch 'main' into fix-1963
larseggert Dec 18, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions .clippy.toml
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,3 +1,4 @@
disallowed-methods = [
{ path = "std::slice::from_raw_parts", reason = "see null_safe_slice" }
]
allow-mixed-uninlined-format-args = false
12 changes: 12 additions & 0 deletions Cargo.lock
View file
Open in desktop

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

3 changes: 3 additions & 0 deletions neqo-bin/Cargo.toml
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
1 change: 0 additions & 1 deletion neqo-bin/benches/main.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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();
Expand Down
3 changes: 1 addition & 2 deletions neqo-bin/src/client/http09.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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()
);
}
Expand Down
4 changes: 2 additions & 2 deletions neqo-bin/src/client/http3.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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 {
Expand Down Expand Up @@ -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)
}
Expand Down
10 changes: 4 additions & 6 deletions neqo-bin/src/client/mod.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -462,7 +462,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;
}
Expand Down Expand Up @@ -553,7 +553,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);
}

Expand All @@ -570,10 +570,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}");
Expand Down
3 changes: 1 addition & 2 deletions neqo-bin/src/lib.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
}
Expand Down
6 changes: 3 additions & 3 deletions neqo-bin/src/server/http09.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
4 changes: 2 additions & 2 deletions neqo-bin/src/server/mod.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -251,7 +251,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;
}
Expand Down Expand Up @@ -360,7 +360,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.
Expand Down
2 changes: 1 addition & 1 deletion neqo-common/Cargo.toml
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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 }
Expand Down
76 changes: 22 additions & 54 deletions neqo-common/src/log.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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()
Expand All @@ -64,52 +33,51 @@ 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)*) => ( { ::neqo_common::log::init(None); ::log::error!($($arg)*); } );
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Could we just use log::trace, etc... directly? I think that most uses of the crate will need to run an init function anyway (for NSS if nothing else), so we can avoid doing the implicit init stuff in a wrapper and rely on people calling the initialization beforehand.

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

See #1963. The issue is that if we use log directly, we need to init the module in each test.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Sounds good. I would observe that perhaps we could keep the wrappers, but avoid the extra initialization step except when we have cfg(test).

}
#[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)*) => ( { ::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)*) => ( { ::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)*) => ( { ::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)*) => ( { ::neqo_common::log::init(None); ::log::trace!($($arg)*); } );
}
8 changes: 2 additions & 6 deletions neqo-common/src/qlog.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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;
}
}
Expand All @@ -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}");
}
}
}
Expand Down
41 changes: 5 additions & 36 deletions neqo-common/tests/log.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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:?}");
}
Loading
Loading