Skip to content

Commit

Permalink
feat(client,server): rework logging (#1692)
Browse files Browse the repository at this point in the history 
* feat(client,server): rework logging

- In `neqo-client` and `neqo-server` use `neqo_common::log` instead of `println!`
  and `eprintln!`.
- Add `-q`, `-v`, `-vv`, `-vvv`, `-vvvv` log level flags via
  `clap_verbosity_flag`.
- Set default log level to INFO. Demote many `qinfo!` to `qdebug!`.

* fix(upload_test.sh): set RUST_LOG debug for neqo_transport::cc

Needed in order for mozlog_neqo_cwnd.py to analyze cc.

* Additional level reductions

* Trigger CI

---------

Co-authored-by: Lars Eggert <lars@eggert.org>
  • Loading branch information
@mxinden @larseggert
mxinden and larseggert authored Mar 21, 2024
1 parent a80db47 commit e4bc0c1
Show file tree
Hide file tree
Showing 21 changed files with 125 additions and 111 deletions.
1 change: 1 addition & 0 deletions neqo-bin/Cargo.toml
View file
Original file line number Diff line number Diff line change
Expand Up @@ -25,6 +25,7 @@ workspace = true
[dependencies]
# neqo-bin is not used in Firefox, so we can be liberal with dependency versions
clap = { version = "4.4", default-features = false, features = ["std", "color", "help", "usage", "error-context", "suggestions", "derive"] }
clap-verbosity-flag = { version = "2.2", default-features = false }
futures = { version = "0.3", default-features = false, features = ["alloc"] }
hex = { version = "0.4", default-features = false, features = ["std"] }
log = { version = "0.4", default-features = false }
Expand Down
26 changes: 13 additions & 13 deletions neqo-bin/src/bin/client/http09.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -17,7 +17,7 @@ use std::{
time::Instant,
};

use neqo_common::{event::Provider, Datagram};
use neqo_common::{event::Provider, qdebug, qinfo, qwarn, Datagram};
use neqo_crypto::{AuthenticationStatus, ResumptionToken};
use neqo_transport::{
Connection, ConnectionEvent, EmptyConnectionIdGenerator, Error, Output, State, StreamId,
Expand Down Expand Up @@ -50,21 +50,21 @@ impl<'a> super::Handler for Handler<'a> {
self.read(client, stream_id)?;
}
ConnectionEvent::SendStreamWritable { stream_id } => {
println!("stream {stream_id} writable");
qdebug!("stream {stream_id} writable");
}
ConnectionEvent::SendStreamComplete { stream_id } => {
println!("stream {stream_id} complete");
qdebug!("stream {stream_id} complete");
}
ConnectionEvent::SendStreamCreatable { stream_type } => {
println!("stream {stream_type:?} creatable");
qdebug!("stream {stream_type:?} creatable");
if stream_type == StreamType::BiDi {
self.download_urls(client);
}
}
ConnectionEvent::StateChange(
State::WaitInitial | State::Handshaking | State::Connected,
) => {
println!("{event:?}");
qdebug!("{event:?}");
self.download_urls(client);
}
ConnectionEvent::StateChange(State::Confirmed) => {
Expand All @@ -74,7 +74,7 @@ impl<'a> super::Handler for Handler<'a> {
self.token = Some(token);
}
_ => {
println!("Unhandled event {event:?}");
qwarn!("Unhandled event {event:?}");
}
}
}
Expand Down Expand Up @@ -187,7 +187,7 @@ impl<'b> Handler<'b> {

fn download_next(&mut self, client: &mut Connection) -> bool {
if self.key_update.needed() {
println!("Deferring requests until after first key update");
qdebug!("Deferring requests until after first key update");
return false;
}
let url = self
Expand All @@ -196,7 +196,7 @@ impl<'b> Handler<'b> {
.expect("download_next called with empty queue");
match client.stream_create(StreamType::BiDi) {
Ok(client_stream_id) => {
println!("Created stream {client_stream_id} for {url}");
qinfo!("Created stream {client_stream_id} for {url}");
let req = format!("GET {}\r\n", url.path());
_ = client
.stream_send(client_stream_id, req.as_bytes())
Expand All @@ -207,7 +207,7 @@ impl<'b> Handler<'b> {
true
}
Err(e @ (Error::StreamLimitError | Error::ConnectionState)) => {
println!("Cannot create stream {e:?}");
qwarn!("Cannot create stream {e:?}");
self.url_queue.push_front(url);
false
}
Expand Down Expand Up @@ -235,9 +235,9 @@ impl<'b> Handler<'b> {
if let Some(out_file) = maybe_out_file {
out_file.write_all(&data[..sz])?;
} else if !output_read_data {
println!("READ[{stream_id}]: {sz} bytes");
qdebug!("READ[{stream_id}]: {sz} bytes");
} else {
println!(
qdebug!(
"READ[{}]: {}",
stream_id,
String::from_utf8(data.clone()).unwrap()
Expand All @@ -252,7 +252,7 @@ impl<'b> Handler<'b> {
fn read(&mut self, client: &mut Connection, stream_id: StreamId) -> Res<()> {
match self.streams.get_mut(&stream_id) {
None => {
println!("Data on unexpected stream: {stream_id}");
qwarn!("Data on unexpected stream: {stream_id}");
return Ok(());
}
Some(maybe_out_file) => {
Expand All @@ -267,7 +267,7 @@ impl<'b> Handler<'b> {
if let Some(mut out_file) = maybe_out_file.take() {
out_file.flush()?;
} else {
println!("<FIN[{stream_id}]>");
qinfo!("<FIN[{stream_id}]>");
}
self.streams.remove(&stream_id);
self.download_urls(client);
Expand Down
26 changes: 13 additions & 13 deletions neqo-bin/src/bin/client/http3.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -18,7 +18,7 @@ use std::{
time::Instant,
};

use neqo_common::{event::Provider, hex, Datagram, Header};
use neqo_common::{event::Provider, hex, qdebug, qinfo, qwarn, Datagram, Header};
use neqo_crypto::{AuthenticationStatus, ResumptionToken};
use neqo_http3::{Error, Http3Client, Http3ClientEvent, Http3Parameters, Http3State, Priority};
use neqo_transport::{
Expand Down Expand Up @@ -149,7 +149,7 @@ impl<'a> super::Handler for Handler<'a> {
if let Some(handler) = self.url_handler.stream_handler(stream_id) {
handler.process_header_ready(stream_id, fin, headers);
} else {
println!("Data on unexpected stream: {stream_id}");
qwarn!("Data on unexpected stream: {stream_id}");
}
if fin {
self.url_handler.on_stream_fin(client, stream_id);
Expand All @@ -159,7 +159,7 @@ impl<'a> super::Handler for Handler<'a> {
let mut stream_done = false;
match self.url_handler.stream_handler(stream_id) {
None => {
println!("Data on unexpected stream: {stream_id}");
qwarn!("Data on unexpected stream: {stream_id}");
}
Some(handler) => loop {
let mut data = vec![0; 4096];
Expand Down Expand Up @@ -193,7 +193,7 @@ impl<'a> super::Handler for Handler<'a> {
Http3ClientEvent::DataWritable { stream_id } => {
match self.url_handler.stream_handler(stream_id) {
None => {
println!("Data on unexpected stream: {stream_id}");
qwarn!("Data on unexpected stream: {stream_id}");
}
Some(handler) => {
handler.process_data_writable(client, stream_id);
Expand All @@ -206,7 +206,7 @@ impl<'a> super::Handler for Handler<'a> {
}
Http3ClientEvent::ResumptionToken(t) => self.token = Some(t),
_ => {
println!("Unhandled event {event:?}");
qwarn!("Unhandled event {event:?}");
}
}
}
Expand Down Expand Up @@ -279,7 +279,7 @@ struct DownloadStreamHandler {
impl StreamHandler for DownloadStreamHandler {
fn process_header_ready(&mut self, stream_id: StreamId, fin: bool, headers: Vec<Header>) {
if self.out_file.is_none() {
println!("READ HEADERS[{stream_id}]: fin={fin} {headers:?}");
qdebug!("READ HEADERS[{stream_id}]: fin={fin} {headers:?}");
}
}

Expand All @@ -297,18 +297,18 @@ impl StreamHandler for DownloadStreamHandler {
}
return Ok(true);
} else if !output_read_data {
println!("READ[{stream_id}]: {sz} bytes");
qdebug!("READ[{stream_id}]: {sz} bytes");
} else if let Ok(txt) = String::from_utf8(data.clone()) {
println!("READ[{stream_id}]: {txt}");
qdebug!("READ[{stream_id}]: {txt}");
} else {
println!("READ[{}]: 0x{}", stream_id, hex(&data));
qdebug!("READ[{}]: 0x{}", stream_id, hex(&data));
}

if fin {
if let Some(mut out_file) = self.out_file.take() {
out_file.flush()?;
} else {
println!("<FIN[{stream_id}]>");
qdebug!("<FIN[{stream_id}]>");
}
}

Expand All @@ -327,7 +327,7 @@ struct UploadStreamHandler {

impl StreamHandler for UploadStreamHandler {
fn process_header_ready(&mut self, stream_id: StreamId, fin: bool, headers: Vec<Header>) {
println!("READ HEADERS[{stream_id}]: fin={fin} {headers:?}");
qdebug!("READ HEADERS[{stream_id}]: fin={fin} {headers:?}");
}

fn process_data_readable(
Expand All @@ -343,7 +343,7 @@ impl StreamHandler for UploadStreamHandler {
let parsed: usize = trimmed_txt.parse().unwrap();
if parsed == self.data.len() {
let upload_time = Instant::now().duration_since(self.start);
println!("Stream ID: {stream_id:?}, Upload time: {upload_time:?}");
qinfo!("Stream ID: {stream_id:?}, Upload time: {upload_time:?}");
}
} else {
panic!("Unexpected data [{}]: 0x{}", stream_id, hex(&data));
Expand Down Expand Up @@ -411,7 +411,7 @@ impl<'a> UrlHandler<'a> {
Priority::default(),
) {
Ok(client_stream_id) => {
println!("Successfully created stream id {client_stream_id} for {url}");
qdebug!("Successfully created stream id {client_stream_id} for {url}");

let handler: Box<dyn StreamHandler> = StreamHandlerType::make_handler(
&self.handler_type,
Expand Down
30 changes: 17 additions & 13 deletions neqo-bin/src/bin/client/main.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -22,7 +22,7 @@ use futures::{
FutureExt, TryFutureExt,
};
use neqo_bin::udp;
use neqo_common::{self as common, qdebug, qinfo, qlog::NeqoQlog, Datagram, Role};
use neqo_common::{self as common, qdebug, qerror, qinfo, qlog::NeqoQlog, qwarn, Datagram, Role};
use neqo_crypto::{
constants::{TLS_AES_128_GCM_SHA256, TLS_AES_256_GCM_SHA384, TLS_CHACHA20_POLY1305_SHA256},
init, Cipher, ResumptionToken,
Expand Down Expand Up @@ -103,7 +103,7 @@ impl KeyUpdateState {
_ => return Err(e),
}
} else {
println!("Keys updated");
qerror!("Keys updated");
self.0 = false;
}
}
Expand All @@ -119,6 +119,9 @@ impl KeyUpdateState {
#[command(author, version, about, long_about = None)]
#[allow(clippy::struct_excessive_bools)] // Not a good use of that lint.
pub struct Args {
#[command(flatten)]
verbose: clap_verbosity_flag::Verbosity<clap_verbosity_flag::InfoLevel>,

#[command(flatten)]
shared: neqo_bin::SharedArgs,

Expand Down Expand Up @@ -211,7 +214,7 @@ impl Args {
"http3" => {
if let Some(testcase) = &self.test {
if testcase.as_str() != "upload" {
eprintln!("Unsupported test case: {testcase}");
qerror!("Unsupported test case: {testcase}");
exit(127)
}

Expand All @@ -223,7 +226,7 @@ impl Args {
}
"zerortt" | "resumption" => {
if self.urls.len() < 2 {
eprintln!("Warning: resumption tests won't work without >1 URL");
qerror!("Warning: resumption tests won't work without >1 URL");
exit(127);
}
self.shared.use_old_http = true;
Expand Down Expand Up @@ -272,11 +275,11 @@ fn get_output_file(
out_path.push(url_path);

if all_paths.contains(&out_path) {
eprintln!("duplicate path {}", out_path.display());
qerror!("duplicate path {}", out_path.display());
return None;
}

eprintln!("Saving {url} to {out_path:?}");
qinfo!("Saving {url} to {out_path:?}");

if let Some(parent) = out_path.parent() {
create_dir_all(parent).ok()?;
Expand Down Expand Up @@ -398,7 +401,7 @@ impl<'a, H: Handler> Runner<'a, H> {
self.socket.send(dgram)?;
}
Output::Callback(new_timeout) => {
qinfo!("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 @@ -444,11 +447,12 @@ fn qlog_new(args: &Args, hostname: &str, cid: &ConnectionId) -> Res<NeqoQlog> {

#[tokio::main]
async fn main() -> Res<()> {
init();

let mut args = Args::parse();
neqo_common::log::init(Some(args.verbose.log_level_filter()));
args.update_for_tests();

init();

let urls_by_origin = args
.urls
.clone()
Expand All @@ -461,14 +465,14 @@ async fn main() -> Res<()> {
.filter_map(|(origin, urls)| match origin {
Origin::Tuple(_scheme, h, p) => Some(((h, p), urls)),
Origin::Opaque(x) => {
eprintln!("Opaque origin {x:?}");
qwarn!("Opaque origin {x:?}");
None
}
});

for ((host, port), mut urls) in urls_by_origin {
if args.resume && urls.len() < 2 {
eprintln!("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 @@ -479,7 +483,7 @@ async fn main() -> Res<()> {
)
});
let Some(remote_addr) = remote_addr else {
eprintln!("No compatible address found for: {host}");
qerror!("No compatible address found for: {host}");
exit(1);
};

Expand All @@ -490,7 +494,7 @@ async fn main() -> Res<()> {

let mut socket = udp::Socket::bind(local_addr)?;
let real_local = socket.local_addr().unwrap();
println!(
qinfo!(
"{} Client connecting: {:?} -> {:?}",
if args.shared.use_old_http { "H9" } else { "H3" },
real_local,
Expand Down
Loading

0 comments on commit e4bc0c1

Please sign in to comment.