From 957199557bb69d528c9702374828ba8fd246b4aa Mon Sep 17 00:00:00 2001 From: Augie Fackler Date: Mon, 27 Jul 2020 22:13:39 -0400 Subject: [PATCH 1/4] main: use Result<()> from anyhow to make error handling easier here As the program grows some configuration, it makes sense to let errors propagate gracefully. --- Cargo.lock | 7 +++++++ Cargo.toml | 1 + src/main.rs | 3 ++- 3 files changed, 10 insertions(+), 1 deletion(-) diff --git a/Cargo.lock b/Cargo.lock index 8f9f258..a3abf9b 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1,5 +1,11 @@ # This file is automatically @generated by Cargo. # It is not intended for manual editing. +[[package]] +name = "anyhow" +version = "1.0.32" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "6b602bfe940d21c130f3895acd65221e8a61270debe89d628b9cb4e3ccb8569b" + [[package]] name = "argv" version = "0.1.2" @@ -55,6 +61,7 @@ dependencies = [ name = "durnitisp" version = "0.1.0" dependencies = [ + "anyhow", "gflags", "nursery", "prometheus", diff --git a/Cargo.toml b/Cargo.toml index 66c88c2..2ee0313 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -7,6 +7,7 @@ edition = "2018" # See more keys and their definitions at https://doc.rust-lang.org/cargo/reference/manifest.html [dependencies] +anyhow = "1" gflags = "^0.3" nursery = "^0.0.1" prometheus = "^0.9.0" diff --git a/src/main.rs b/src/main.rs index 5cd0200..481071a 100644 --- a/src/main.rs +++ b/src/main.rs @@ -97,7 +97,7 @@ fn attempt_stun_connect(addr: SocketAddr) -> Result { Ok(SystemTime::now()) } -fn main() { +fn main() -> anyhow::Result<()> { let default_stun_servers: Vec<&'static str> = vec![ "stun.l.google.com:19302", "stun.ekiga.net:3478", @@ -217,4 +217,5 @@ fn main() { parent.schedule(Box::new(render_thread)); // Blocks forever parent.wait(); + Ok(()) } From 35914251bfd5ae6deae4054e53fb1aac1d338781 Mon Sep 17 00:00:00 2001 From: Augie Fackler Date: Mon, 27 Jul 2020 22:18:16 -0400 Subject: [PATCH 2/4] logging: convert existing eprintln calls to log calls I tried to categorize them appropriately. --- Cargo.lock | 110 +++++++++++++++++++++++++++++++++++++++++++++++++++- Cargo.toml | 2 + src/main.rs | 23 ++++++----- 3 files changed, 125 insertions(+), 10 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index a3abf9b..76f20b8 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -18,6 +18,17 @@ version = "1.0.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "bbf56136a5198c7b01a49e3afcbef6cf84597273d298f54432926024107b0109" +[[package]] +name = "atty" +version = "0.2.11" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "9a7d5b8723950951411ee34d271d99dddcc2035a16ab25310ea2c8cfd4369652" +dependencies = [ + "libc", + "termion", + "winapi", +] + [[package]] name = "autocfg" version = "1.0.0" @@ -63,8 +74,10 @@ version = "0.1.0" dependencies = [ "anyhow", "gflags", + "log", "nursery", "prometheus", + "stderrlog", "tiny_http", ] @@ -141,6 +154,12 @@ dependencies = [ "syn", ] +[[package]] +name = "lazy_static" +version = "0.2.11" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "76f033c7ad61445c5b347c7382dd1237847eb1bce590fe50365dcb33d546be73" + [[package]] name = "lazy_static" version = "1.4.0" @@ -187,6 +206,12 @@ dependencies = [ "autocfg", ] +[[package]] +name = "numtoa" +version = "0.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "b8f8bdf33df195859076e54ab11ee78a1b208382d3a26ec40d142ffc1ecc49ef" + [[package]] name = "nursery" version = "0.0.1" @@ -216,7 +241,7 @@ checksum = "dd0ced56dee39a6e960c15c74dc48849d614586db2eaada6497477af7c7811cd" dependencies = [ "cfg-if", "fnv", - "lazy_static", + "lazy_static 1.4.0", "protobuf", "spin", "thiserror", @@ -237,6 +262,21 @@ dependencies = [ "proc-macro2", ] +[[package]] +name = "redox_syscall" +version = "0.1.57" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "41cc0f7e4d5d4544e8861606a285bb08d3e70712ccc7d2b84d7c0ccfaf4b05ce" + +[[package]] +name = "redox_termios" +version = "0.1.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "7e891cfe48e9100a70a3b6eb652fef28920c117d366339687bd5576160db0f76" +dependencies = [ + "redox_syscall", +] + [[package]] name = "ref-cast" version = "1.0.2" @@ -263,6 +303,19 @@ version = "0.5.2" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "6e63cff320ae2c57904679ba7cb63280a3dc4613885beafb148ee7bf9aa9042d" +[[package]] +name = "stderrlog" +version = "0.4.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "32e5ee9b90a5452c570a0b0ac1c99ae9498db7e56e33d74366de7f2a7add7f25" +dependencies = [ + "atty", + "chrono", + "log", + "termcolor", + "thread_local", +] + [[package]] name = "syn" version = "1.0.33" @@ -274,6 +327,27 @@ dependencies = [ "unicode-xid", ] +[[package]] +name = "termcolor" +version = "1.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "bb6bfa289a4d7c5766392812c0a1f4c1ba45afa1ad47803c11e1f407d846d75f" +dependencies = [ + "winapi-util", +] + +[[package]] +name = "termion" +version = "1.5.5" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "c22cec9d8978d906be5ac94bceb5a010d885c626c4c8855721a4dbd20e3ac905" +dependencies = [ + "libc", + "numtoa", + "redox_syscall", + "redox_termios", +] + [[package]] name = "thiserror" version = "1.0.20" @@ -294,6 +368,16 @@ dependencies = [ "syn", ] +[[package]] +name = "thread_local" +version = "0.3.4" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "1697c4b57aeeb7a536b647165a2825faddffb1d3bad386d507709bd51a90bb14" +dependencies = [ + "lazy_static 0.2.11", + "unreachable", +] + [[package]] name = "time" version = "0.1.43" @@ -347,6 +431,15 @@ version = "0.2.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "f7fe0bb3479651439c9112f72b6c505038574c9fbb575ed1bf3b797fa39dd564" +[[package]] +name = "unreachable" +version = "1.0.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "382810877fe448991dfc7f0dd6e3ae5d58088fd0ea5e35189655f84e6814fa56" +dependencies = [ + "void", +] + [[package]] name = "url" version = "2.1.1" @@ -358,6 +451,12 @@ dependencies = [ "percent-encoding", ] +[[package]] +name = "void" +version = "1.0.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "6a02e4885ed3bc0f2de90ea6dd45ebcbb66dacffe03547fadbb0eeae2770887d" + [[package]] name = "winapi" version = "0.3.9" @@ -374,6 +473,15 @@ version = "0.4.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "ac3b87c63620426dd9b991e5ce0329eff545bccbbb34f3be09ff6fb6ab51b7b6" +[[package]] +name = "winapi-util" +version = "0.1.5" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "70ec6ce85bb158151cae5e5c87f95a8e97d2c0c4b001223f33a334e3ce5de178" +dependencies = [ + "winapi", +] + [[package]] name = "winapi-x86_64-pc-windows-gnu" version = "0.4.0" diff --git a/Cargo.toml b/Cargo.toml index 2ee0313..ea50ee1 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -9,6 +9,8 @@ edition = "2018" [dependencies] anyhow = "1" gflags = "^0.3" +log = "0.4" nursery = "^0.0.1" prometheus = "^0.9.0" +stderrlog = "0.4" tiny_http = "^0.7.0" \ No newline at end of file diff --git a/src/main.rs b/src/main.rs index 481071a..b5c22d3 100644 --- a/src/main.rs +++ b/src/main.rs @@ -25,6 +25,8 @@ use prometheus; use prometheus::{CounterVec, Encoder, IntGaugeVec, Opts, Registry, TextEncoder}; use tiny_http; +use log::{error, info}; + gflags::define! { /// Print this help text. -h, --help = false @@ -74,7 +76,7 @@ fn resolve_addrs(servers: &Vec<&str>) -> io::Result> { // TODO for resolution errors return a more valid error with the domain name. match name.to_socket_addrs() { Ok(addr) => results.extend(addr), - Err(e) => eprintln!("Failed to resolve {} with error {}", name, e), + Err(e) => info!("Failed to resolve {} with error {}", name, e), } } return Ok(results); @@ -116,6 +118,9 @@ fn main() -> anyhow::Result<()> { println!("FLAGS:"); gflags::print_help_and_exit(0); } + + stderrlog::new().verbosity(2).init()?; + if stun_servers.is_empty() { stun_servers = default_stun_servers; } @@ -149,10 +154,10 @@ fn main() -> anyhow::Result<()> { let connect_thread = thread::Pending::new(move || { loop { let now = SystemTime::now(); - eprintln!("Attempting to connect to {}", domain_name); + info!("Attempting to connect to {}", domain_name); match attempt_stun_connect(s) { Ok(finish_time) => { - eprintln!("Success! connecting to {}", domain_name); + info!("Success! connecting to {}", domain_name); stun_counter_vec_copy .with(&prometheus::labels! {"result" => "ok", "domain" => domain_name}) .inc(); @@ -162,7 +167,7 @@ fn main() -> anyhow::Result<()> { .set(finish_time.duration_since(now).unwrap().as_millis() as i64); } Err(ConnectError::Timeout(finish_time)) => { - eprintln!( + info!( "Stun connection to {} timedout after {} millis", domain_name, finish_time.duration_since(now).unwrap().as_millis() @@ -172,13 +177,13 @@ fn main() -> anyhow::Result<()> { .inc(); } Err(ConnectError::Err(e)) => { - eprintln!("Error connecting to {}: {}", domain_name, e); + error!("Error connecting to {}: {}", domain_name, e); stun_counter_vec_copy .with(&prometheus::labels! {"result" => "err", "domain" => domain_name}) .inc(); } Err(ConnectError::Incomplete) => { - eprintln!("Connection to {} was incomplete", domain_name); + error!("Connection to {} was incomplete", domain_name); stun_counter_vec_copy .with(&prometheus::labels! {"result" => "incomplete", "domain" => domain_name}) .inc(); @@ -194,7 +199,7 @@ fn main() -> anyhow::Result<()> { let render_thread = thread::Pending::new(move || { let server = tiny_http::Server::http(LISTENHOST.flag).unwrap(); loop { - eprintln!("Waiting for request"); + info!("Waiting for request"); match server.recv() { Ok(req) => { let mut buffer = vec![]; @@ -205,11 +210,11 @@ fn main() -> anyhow::Result<()> { let response = tiny_http::Response::from_data(buffer).with_status_code(200); if let Err(e) = req.respond(response) { - eprintln!("Error responding to request {}", e); + info!("Error responding to request {}", e); } } Err(e) => { - eprintln!("Invalid http request! {}", e); + info!("Invalid http request! {}", e); } } } From c4a069f24610c761d3bb597c55269d4300d401aa Mon Sep 17 00:00:00 2001 From: Augie Fackler Date: Mon, 27 Jul 2020 22:19:32 -0400 Subject: [PATCH 3/4] logging: sprinkle some debug logs throughout --- src/main.rs | 12 ++++++++++-- 1 file changed, 10 insertions(+), 2 deletions(-) diff --git a/src/main.rs b/src/main.rs index b5c22d3..e9621c2 100644 --- a/src/main.rs +++ b/src/main.rs @@ -25,7 +25,7 @@ use prometheus; use prometheus::{CounterVec, Encoder, IntGaugeVec, Opts, Registry, TextEncoder}; use tiny_http; -use log::{error, info}; +use log::{debug, error, info}; gflags::define! { /// Print this help text. @@ -47,6 +47,11 @@ gflags::define! { --stunRecvTimeoutSecs: u64 = 5 } +gflags::define! { + /// Enable debug logging + --debug = false +} + const STUN_PAYLOAD: [u8; 20] = [ 0, 1, // Binding request 0, 0, // Message length @@ -119,7 +124,8 @@ fn main() -> anyhow::Result<()> { gflags::print_help_and_exit(0); } - stderrlog::new().verbosity(2).init()?; + let level = if DEBUG.flag { 3 } else { 2 }; + stderrlog::new().verbosity(level).init()?; if stun_servers.is_empty() { stun_servers = default_stun_servers; @@ -152,6 +158,7 @@ fn main() -> anyhow::Result<()> { let s = s.clone(); let domain_name = *stun_servers_copy.get(i).unwrap(); let connect_thread = thread::Pending::new(move || { + debug!("started thread for {}", domain_name); loop { let now = SystemTime::now(); info!("Attempting to connect to {}", domain_name); @@ -197,6 +204,7 @@ fn main() -> anyhow::Result<()> { parent.schedule(Box::new(connect_thread)); } let render_thread = thread::Pending::new(move || { + debug!("attempting to start server on {}", LISTENHOST.flag); let server = tiny_http::Server::http(LISTENHOST.flag).unwrap(); loop { info!("Waiting for request"); From 91f04b3fe97dbfbfb003bca367a570cac7008122 Mon Sep 17 00:00:00 2001 From: Augie Fackler Date: Mon, 27 Jul 2020 22:55:13 -0400 Subject: [PATCH 4/4] logging: include a timestamp with millisecond precision --- src/main.rs | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/src/main.rs b/src/main.rs index e9621c2..0390f40 100644 --- a/src/main.rs +++ b/src/main.rs @@ -125,7 +125,10 @@ fn main() -> anyhow::Result<()> { } let level = if DEBUG.flag { 3 } else { 2 }; - stderrlog::new().verbosity(level).init()?; + stderrlog::new() + .verbosity(level) + .timestamp(stderrlog::Timestamp::Millisecond) + .init()?; if stun_servers.is_empty() { stun_servers = default_stun_servers;