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

Jump to bottom

feat(client,server): rework logging #1692

Merged
merged 5 commits into from
Mar 21, 2024
Merged

feat(client,server): rework logging #1692

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
5 commits
Select commit Hold shift + click to select a range
e2732e6
feat(client,server): rework logging
mxinden Mar 19, 2024
b090a93
fix(upload_test.sh): set RUST_LOG debug for neqo_transport::cc
mxinden Mar 21, 2024
46bcb9b
Additional level reductions
mxinden Mar 21, 2024
3a048af
Trigger CI
mxinden Mar 21, 2024
4227f8d
Merge branch 'main' into common-log
larseggert Mar 21, 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 neqo-bin/Cargo.toml
View file
Open in desktop
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
Open in desktop
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 @@ -183,7 +183,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 @@ -192,7 +192,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 @@ -203,7 +203,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 @@ -231,9 +231,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 @@ -248,7 +248,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 @@ -263,7 +263,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
Open in desktop
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 @@ -145,7 +145,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 @@ -155,7 +155,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 @@ -189,7 +189,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 @@ -202,7 +202,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 @@ -275,7 +275,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 @@ -293,18 +293,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 @@ -323,7 +323,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 @@ -339,7 +339,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 @@ -407,7 +407,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
Open in desktop
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 @@ -207,7 +210,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 @@ -219,7 +222,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 @@ -268,11 +271,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 @@ -390,7 +393,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 @@ -436,11 +439,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 @@ -453,14 +457,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 @@ -471,7 +475,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 @@ -482,7 +486,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
Loading