From 2cea3a294e604459fced4bea99cb50938534f76e Mon Sep 17 00:00:00 2001 From: Jeremy Wall Date: Thu, 14 Jul 2022 21:13:05 -0400 Subject: [PATCH] Update to tracing for logs --- Cargo.lock | 192 ++++++++++++++++++++++++++++------------------------ Cargo.toml | 4 +- src/icmp.rs | 102 +++++++++++++++++----------- src/main.rs | 50 +++++++++----- src/stun.rs | 37 +++++++--- src/util.rs | 5 +- 6 files changed, 230 insertions(+), 160 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 3ec30e4..447c969 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1,5 +1,7 @@ # This file is automatically @generated by Cargo. # It is not intended for manual editing. +version = 3 + [[package]] name = "aho-corasick" version = "0.7.15" @@ -9,6 +11,15 @@ dependencies = [ "memchr", ] +[[package]] +name = "ansi_term" +version = "0.12.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "d52a9bb7ec0cf484c551830a7ce27bd20d67eac647e1befb56b0be4ee39a55d2" +dependencies = [ + "winapi", +] + [[package]] name = "anyhow" version = "1.0.38" @@ -27,29 +38,12 @@ 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.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "cdb031dd78e28731d87d56cc8ffef4a8f36ca26c38fe2de700543e627f8a464a" -[[package]] -name = "bitflags" -version = "1.2.1" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "cf1de2fe8c75bc145a2f577add951f8134889b4795d47466a54a5c846d691693" - [[package]] name = "byteorder" version = "1.4.2" @@ -98,13 +92,13 @@ dependencies = [ "anyhow", "gflags", "icmp-socket", - "log 0.4.14", "nursery", "prometheus", "resolve", "socket2", - "stderrlog", "tiny_http", + "tracing", + "tracing-subscriber", ] [[package]] @@ -296,18 +290,18 @@ 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" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "a4bd2d4e0cd7c6bb256afbc59a5921c3ead56f05d7696c92e05b6978858b6fa5" +[[package]] +name = "once_cell" +version = "1.13.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "18a6dbe30758c9f83eb00cbea4ac95966305f5a7772f3f42ebfc7fc7eddbd8e1" + [[package]] name = "parking_lot" version = "0.11.1" @@ -328,7 +322,7 @@ dependencies = [ "cfg-if", "instant", "libc", - "redox_syscall 0.1.57", + "redox_syscall", "smallvec", "winapi", ] @@ -339,6 +333,12 @@ version = "2.1.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "d4fd5641d01c8f18a23da7b6fe29298ff4b55afcccdf78973b24cf3175fee32e" +[[package]] +name = "pin-project-lite" +version = "0.2.9" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "e0a7ae3ac2f1173085d398531c705756c94a4c56843785df85a60c1a0afac116" + [[package]] name = "proc-macro2" version = "1.0.24" @@ -431,24 +431,6 @@ version = "0.1.57" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "41cc0f7e4d5d4544e8861606a285bb08d3e70712ccc7d2b84d7c0ccfaf4b05ce" -[[package]] -name = "redox_syscall" -version = "0.2.4" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "05ec8ca9416c5ea37062b502703cd7fcb207736bc294f6e0cf367ac6fc234570" -dependencies = [ - "bitflags", -] - -[[package]] -name = "redox_termios" -version = "0.1.2" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "8440d8acb4fd3d277125b4bd01a6f38aee8d814b3b5fc09b3f2b825d37d3fe8f" -dependencies = [ - "redox_syscall 0.2.4", -] - [[package]] name = "ref-cast" version = "1.0.6" @@ -505,6 +487,15 @@ version = "1.1.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "d29ab0c6d3fc0ee92fe66e2d99f700eab17a8d57d1c1d3b748380fb20baa78cd" +[[package]] +name = "sharded-slab" +version = "0.1.4" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "900fba806f70c630b0a382d0d825e17a0f19fcd059a2ade1ff237bcddf446b31" +dependencies = [ + "lazy_static", +] + [[package]] name = "smallvec" version = "1.6.1" @@ -522,19 +513,6 @@ dependencies = [ "winapi", ] -[[package]] -name = "stderrlog" -version = "0.5.1" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "45a53e2eff3e94a019afa6265e8ee04cb05b9d33fe9f5078b14e4e391d155a38" -dependencies = [ - "atty", - "chrono", - "log 0.4.14", - "termcolor", - "thread_local", -] - [[package]] name = "syn" version = "1.0.60" @@ -546,27 +524,6 @@ dependencies = [ "unicode-xid", ] -[[package]] -name = "termcolor" -version = "1.1.2" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "2dfed899f0eb03f32ee8c6a0aabdb8a7949659e3466561fc0adf54e26d88c5f4" -dependencies = [ - "winapi-util", -] - -[[package]] -name = "termion" -version = "1.5.6" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "077185e2eac69c3f8379a4298e1e07cd36beb962290d4a51199acf0fdc10607e" -dependencies = [ - "libc", - "numtoa", - "redox_syscall 0.2.4", - "redox_termios", -] - [[package]] name = "thiserror" version = "1.0.23" @@ -589,11 +546,11 @@ dependencies = [ [[package]] name = "thread_local" -version = "1.0.1" +version = "1.1.4" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "d40c6d1b69745a6ec6fb1ca717914848da4b44ae29d9b3080cbee91d72a69b14" +checksum = "5516c27b78311c50bf42c071425c560ac799b11c30b31f87e3081965fe5e0180" dependencies = [ - "lazy_static", + "once_cell", ] [[package]] @@ -635,6 +592,64 @@ version = "0.1.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "cda74da7e1a664f795bb1f8a87ec406fb89a02522cf6e50620d016add6dbbf5c" +[[package]] +name = "tracing" +version = "0.1.35" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "a400e31aa60b9d44a52a8ee0343b5b18566b03a8321e0d321f695cf56e940160" +dependencies = [ + "cfg-if", + "pin-project-lite", + "tracing-attributes", + "tracing-core", +] + +[[package]] +name = "tracing-attributes" +version = "0.1.22" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "11c75893af559bc8e10716548bdef5cb2b983f8e637db9d0e15126b61b484ee2" +dependencies = [ + "proc-macro2", + "quote", + "syn", +] + +[[package]] +name = "tracing-core" +version = "0.1.28" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "7b7358be39f2f274f322d2aaed611acc57f382e8eb1e5b48cb9ae30933495ce7" +dependencies = [ + "once_cell", + "valuable", +] + +[[package]] +name = "tracing-log" +version = "0.1.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "78ddad33d2d10b1ed7eb9d1f518a5674713876e97e5bb9b7345a7984fbb4f922" +dependencies = [ + "lazy_static", + "log 0.4.14", + "tracing-core", +] + +[[package]] +name = "tracing-subscriber" +version = "0.3.14" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "3a713421342a5a666b7577783721d3117f1b69a393df803ee17bb73b1e122a59" +dependencies = [ + "ansi_term", + "sharded-slab", + "smallvec", + "thread_local", + "tracing-core", + "tracing-log", +] + [[package]] name = "unicode-bidi" version = "0.3.4" @@ -671,6 +686,12 @@ dependencies = [ "percent-encoding", ] +[[package]] +name = "valuable" +version = "0.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "830b7e5d4d90034032940e4ace0d9a9a057e7a45cd94e6c007832e39edb82f6d" + [[package]] name = "wasi" version = "0.10.0+wasi-snapshot-preview1" @@ -693,15 +714,6 @@ 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 f5d77cd..205857e 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -7,12 +7,12 @@ edition = "2018" # See more keys and their definitions at https://doc.rust-lang.org/cargo/reference/manifest.html [dependencies] +tracing = "0.1.35" +tracing-subscriber = "0.3.14" anyhow = "1" gflags = "^0.3" -log = "0.4" nursery = "^0.0.1" prometheus = "0.11.0" -stderrlog = "0.5.1" tiny_http = "0.8.0" socket2 = "0.3.19" icmp-socket = "0.1.1" diff --git a/src/icmp.rs b/src/icmp.rs index aaea847..b663c2e 100644 --- a/src/icmp.rs +++ b/src/icmp.rs @@ -25,9 +25,9 @@ use icmp_socket::{ packet::{Icmpv4Message, Icmpv6Message, WithEchoRequest}, IcmpSocket, IcmpSocket4, IcmpSocket6, Icmpv4Packet, Icmpv6Packet, }; -use log::{debug, error, info}; use nursery::{thread, Nursery}; use prometheus::{CounterVec, GaugeVec}; +use tracing::{debug, error, info, instrument, warn}; gflags::define! { /// The payload to use for the ping requests. @@ -87,8 +87,9 @@ impl<'a> PacketHandler for &'a mut State { return self; } + #[instrument(level = "debug", skip(self))] fn handle_pkt(&mut self, pkt: Icmpv6Packet) -> bool { - debug!("ICMP: handling packet {:?}", pkt); + debug!("handling packet"); match pkt.message { Icmpv6Message::Unreachable { _unused, @@ -115,7 +116,7 @@ impl<'a> PacketHandler for &'a mut State { } Err(e) => { // We ignore these as well but log it. - error!("ICMP: Error parsing Unreachable invoking packet {:?}", e); + error!(err = ?e, "Error parsing Unreachable"); } _ => { // We ignore these @@ -147,7 +148,7 @@ impl<'a> PacketHandler for &'a mut State { } Err(e) => { // We ignore these as well but log it. - error!("ICMP: Error parsing Unreachable invoking packet {:?}", e); + error!(err = ?e, "Error parsing ParameterProblem"); } _ => { // We ignore these @@ -169,16 +170,20 @@ impl<'a> PacketHandler for &'a mut State { let expected_sequence = *expected_sequence; if sequence != expected_sequence { error!( - "ICMP: Discarding unexpected sequence sequence={} expected={}", - sequence, expected_sequence + sequence, + expected = expected_sequence, + "Discarding unexpected sequence", ); self.time_tracker .insert(identifier, (None, expected_sequence.wrapping_add(1))); return false; } info!( - "ICMP: Reply from {}({}): time={}ms, seq={}", - domain_name, dest, elapsed, sequence, + domain=domain_name, + %dest, + time = elapsed, + seq = sequence, + "Reply", ); self.ping_counter .with(&prometheus::labels! {"result" => "ok", "domain" => domain_name}) @@ -195,7 +200,7 @@ impl<'a> PacketHandler for &'a mut State { return false; }; } else { - info!("ICMP: Discarding wrong identifier {}", identifier); + warn!(identifier, "Discarding wrong identifier"); } } _ => { @@ -211,8 +216,9 @@ impl<'a> PacketHandler for &'a mut State { return self; } + #[instrument(level = "debug", skip(self))] fn handle_pkt(&mut self, pkt: Icmpv4Packet) -> bool { - debug!("ICMP: handling packet {:?}", pkt); + debug!("handling packet"); match pkt.message { Icmpv4Message::EchoReply { identifier, @@ -228,17 +234,15 @@ impl<'a> PacketHandler for &'a mut State { let expected_sequence = *expected_sequence; if expected_sequence != sequence { error!( - "ICMP: Discarding unexpected sequence sequence={} expected={}", - sequence, expected_sequence + sequence, + expected = expected_sequence, + "Discarding unexpected sequence", ); self.time_tracker .insert(identifier, (None, expected_sequence.wrapping_add(1))); return false; } - info!( - "ICMP: Reply from {}({}): time={}ms, seq={}", - domain_name, dest, elapsed, sequence, - ); + info!(domain=domain_name, %dest, time = elapsed, seq = sequence, "Reply",); self.ping_counter .with(&prometheus::labels! {"result" => "ok", "domain" => domain_name}) .inc(); @@ -252,12 +256,12 @@ impl<'a> PacketHandler for &'a mut State { return false; }; } else { - info!("ICMP: Discarding wrong identifier {}", identifier); + info!(identifier, "Discarding wrong identifier"); } } - p => { + _ => { // We ignore the rest. - info!("ICMP Unhandled packet {:?}", p); + info!("Unhandled packet"); } } return false; @@ -287,9 +291,10 @@ where Sock::AddrType: std::fmt::Display + Copy, Sock::PacketType: WithEchoRequest, { + #[instrument(skip(self, state))] fn send_all(&mut self, state: &mut State) -> std::io::Result<()> { let destinations = state.destinations.clone(); - info!("ICMP: Attempting to send packets for all domains"); + debug!("Attempting to send packets for all domains"); for (identifier, (domain_name, dest)) in destinations.into_iter() { let previous_tracker = state.time_tracker.get(&identifier); let sequence = if previous_tracker.is_some() { @@ -300,8 +305,11 @@ where let elapsed = Instant::now() - *send_time; if elapsed > Duration::from_secs(PINGTIMEOUT.flag) { info!( - "ICMP: Dropped packet detected for domain_name={} send_time={:?} elapsed={:?} sequence={}", - domain_name, send_time, elapsed, sequence + domain = domain_name, + ?send_time, + ?elapsed, + seq = sequence, + "Dropped packet detected", ); state.ping_counter .with(&prometheus::labels! {"result" => "dropped", "domain" => &domain_name}) @@ -309,8 +317,9 @@ where sequence.wrapping_add(1) } else { debug!( - "ICMP: Waiting for timeout before sending next packet domain_name={} sequence={}", - domain_name, sequence + domain = domain_name, + seq = sequence, + "Waiting for timeout before sending next packet", ); continue; } @@ -319,14 +328,15 @@ where } } else { debug!( - "ICMP: Initializing sequence for first send domain_name={} sequence=0", - domain_name + domain = domain_name, + seq = 0 as u16, + "Initializing sequence for first send", ); 0 }; - info!( - "ICMP: sending echo request to {}({}) sequence={}", - domain_name, dest, sequence + debug!( + domain=domain_name, %dest, sequence, + "Sending echo request", ); match self.send_to_destination(dest, identifier, sequence) { Err(e) => { @@ -335,9 +345,9 @@ where .with(&prometheus::labels! {"result" => "err", "type" => "send"}) .inc(); error!( - "ICMP: error sending to domain: {} and address: {} failed: {:?}, Trying again later", - domain_name, &dest, e - ); + domain=domain_name, %dest, err=?e, + "Error sending. Trying again later", + ); } Ok(send_time) => { state @@ -346,7 +356,7 @@ where } } } - debug!("ICMP: finished sending for domains"); + debug!("Finished sending for domains"); Ok(()) } @@ -372,6 +382,7 @@ where Ok(response) } + #[instrument(skip(self, handler))] fn recv_all>(&mut self, mut handler: H) { if handler.get_mut_state().destinations.is_empty() { debug!("Nothing to send to so skipping for this socket"); @@ -394,17 +405,17 @@ where let loop_start_time = Instant::now(); loop { // Receive loop - debug!("ICMP: Attempting to recieve packets on socket"); + debug!("Attempting to recieve packets on socket"); match self.recv_pkt() { Ok(pkt) => { if handler.handle_pkt(pkt) { // break out of the recv loop - debug!("ICMP: Recieved Packet"); + debug!("Recieved Packet"); return; } } Err(e) => { - error!("ICMP: Error receiving packet: {:?}", e); + error!(err = ?e, "Error receiving packet"); handler .get_mut_state() .ping_counter @@ -414,7 +425,7 @@ where } } if (Instant::now() - loop_start_time) > Duration::from_secs(PINGTIMEOUT.flag) { - info!("ICMP: Timing out on recieve loop"); + info!("Timing out on recieve loop"); return; } } @@ -444,6 +455,7 @@ impl Multi { } } +#[instrument(name = "ICMP", skip_all)] pub fn schedule_echo_server( domain_names: &Vec<&str>, ping_latency_guage: GaugeVec, @@ -476,7 +488,11 @@ pub fn schedule_echo_server( let mut v4_destinations = HashMap::new(); let mut v4_id_counter = 42; for target in v4_targets { - info!("ICMP: Attempting ping to {}({})", target.0, target.1); + info!( + domain_name = target.0, + address = %target.1, + "Attempting ping" + ); v4_destinations.insert(v4_id_counter, target.clone()); v4_id_counter += 1; } @@ -489,7 +505,11 @@ pub fn schedule_echo_server( let mut v6_destinations = HashMap::new(); let mut v6_id_counter = 42; for target in v6_targets { - info!("ICMP: Attempting ping to {}({})", target.0, target.1); + info!( + domain_name = target.0, + address = %target.1, + "Attempting ping" + ); v6_destinations.insert(v6_id_counter, target.clone()); v6_id_counter += 1; } @@ -515,7 +535,7 @@ pub fn schedule_echo_server( })); let send_multi = multi.clone(); let send_thread = thread::Pending::new(move || { - info!("ICMP: Starrting send thread"); + info!("Starting send thread"); loop { { send_multi.lock().unwrap().send_all(); @@ -524,7 +544,7 @@ pub fn schedule_echo_server( } }); let recv_thread = thread::Pending::new(move || { - info!("ICMP: Starrting recv thread"); + info!("Starting recv thread"); loop { { multi.lock().unwrap().recv_all(); diff --git a/src/main.rs b/src/main.rs index d60c4fb..ca41e28 100644 --- a/src/main.rs +++ b/src/main.rs @@ -11,18 +11,17 @@ // WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. // See the License for the specific language governing permissions and // limitations under the License. - use std::convert::Into; use std::sync::Arc; use gflags; -use log::{debug, error, info}; use nursery::thread; use nursery::{Nursery, Waitable}; use prometheus::{self, GaugeVec}; use prometheus::{CounterVec, Encoder, IntGaugeVec, Opts, Registry, TextEncoder}; -use stderrlog; use tiny_http; +use tracing::{debug, error, info, instrument, Level}; +use tracing_subscriber::FmtSubscriber; mod icmp; mod stun; @@ -43,6 +42,11 @@ gflags::define! { --debug = false } +gflags::define! { + /// Enable trace logging + --trace = false +} + gflags::define! { /// Comma separated list of hosts to ping --pingHosts = "google.com" @@ -53,6 +57,7 @@ gflags::define! { --stunHosts = "stun.l.google.com:19302,stun.ekiga.net:3478,stun.xten.com:3478,stun.ideasip.com:3478,stun.rixtelecom.se:3478,stun.schlund.de:3478,stun.softjoys.com:3478,stun.stunprotocol.org:3478,stun.voiparound.com:3478,stun.voipbuster.com:3478,stun.voipstunt.com:3478,stun1.noc.ams-ix.net:3478" } +#[instrument] fn main() -> anyhow::Result<()> { gflags::parse(); let stun_servers: Vec<&str> = STUNHOSTS.flag.split(",").collect(); @@ -67,16 +72,24 @@ fn main() -> anyhow::Result<()> { gflags::print_help_and_exit(0); } - let level = if DEBUG.flag || cfg!(debug_assertions) { - 3 + let subscriber_builder = if DEBUG.flag { + FmtSubscriber::builder() + // all spans/events with a level higher than debug + // will be written to stdout. + .with_max_level(Level::DEBUG) + } else if TRACE.flag { + FmtSubscriber::builder() + // all spans/events with a level will be written to stdout. + .with_max_level(Level::TRACE) } else { - 2 + FmtSubscriber::builder() + // all spans/events with a level higher than info (e.g, error, info, warn, etc.) + // will be written to stdout. + .with_max_level(Level::INFO) }; - stderrlog::new() - .verbosity(level) - .timestamp(stderrlog::Timestamp::Millisecond) - .init()?; + tracing::subscriber::set_global_default(subscriber_builder.finish()) + .expect("setting default subscriber failed"); let ping_hosts: Vec<&str> = PINGHOSTS.flag.split(",").collect(); @@ -130,16 +143,21 @@ fn main() -> anyhow::Result<()> { // Introduce a new scope for our Arc to clone before moving it into the thread. // thread::Handle starts the thread immediately so the render thread will usually start first. let render_thread = thread::Handle::new(move || { - debug!("attempting to start server on {}", LISTENHOST.flag); + debug!(listenhost = LISTENHOST.flag, "attempting to start server"); let server = match tiny_http::Server::http(LISTENHOST.flag) { Ok(server) => server, Err(err) => { - error!("Error starting render thread {}", err); - error!("Shutting down all threads..."); + error!( + ?err, + "Error starting render thread. Shutting down all thread.", + ); std::process::exit(1); } }; - info!("Listening for metrics request on {}", LISTENHOST.flag); + info!( + listenthost = LISTENHOST.flag, + "Listening for metrics request on" + ); loop { info!("Waiting for request"); match server.recv() { @@ -152,11 +170,11 @@ fn main() -> anyhow::Result<()> { let response = tiny_http::Response::from_data(buffer).with_status_code(200); if let Err(e) = req.respond(response) { - error!("Error responding to request {}", e); + error!(err = ?e, "Error responding to request"); } } Err(e) => { - info!("Invalid http request! {}", e); + error!(err = ?e, "Invalid http request!"); } } } diff --git a/src/stun.rs b/src/stun.rs index 8618e09..1b4254b 100644 --- a/src/stun.rs +++ b/src/stun.rs @@ -13,12 +13,12 @@ // limitations under the License. use gflags; -use log::{debug, error, info}; use prometheus::{CounterVec, IntGaugeVec}; use std::convert::From; use std::io; use std::net::{SocketAddr, UdpSocket}; use std::time::SystemTime; +use tracing::{debug, error, info, instrument}; gflags::define! { /// Read timeout for the stun server udp receive @@ -70,6 +70,11 @@ fn attempt_stun_connect(addr: SocketAddr) -> Result { Ok(SystemTime::now()) } +#[instrument( + name = "STUN", + fields(domain=domain_name, socket=%s), + skip(stun_counter_vec_copy, stun_latency_vec_copy, stun_success_vec_copy) +)] pub fn start_listen_thread( domain_name: &str, s: SocketAddr, @@ -77,13 +82,18 @@ pub fn start_listen_thread( stun_latency_vec_copy: IntGaugeVec, stun_success_vec_copy: IntGaugeVec, ) { - debug!("started thread for {}", domain_name); + debug!("starting thread"); loop { let now = SystemTime::now(); - info!("Attempting to connect to {}", domain_name); + info!("Attempting to connect"); match attempt_stun_connect(s) { Ok(finish_time) => { - info!("Success! connecting to {}", domain_name); + info!( + timeout = false, + success = true, + millis = finish_time.duration_since(now).unwrap().as_millis(), + conn_type = "Stun connection", + ); stun_counter_vec_copy .with(&prometheus::labels! {"result" => "ok", "domain" => domain_name}) .inc(); @@ -97,9 +107,10 @@ pub fn start_listen_thread( } Err(ConnectError::Timeout(finish_time)) => { info!( - "Stun connection to {} timedout after {} millis", - domain_name, - finish_time.duration_since(now).unwrap().as_millis() + timeout = true, + success = false, + millis = finish_time.duration_since(now).unwrap().as_millis(), + conn_type = "Stun connection", ); stun_counter_vec_copy .with(&prometheus::labels! {"result" => "timeout", "domain" => domain_name}) @@ -109,7 +120,10 @@ pub fn start_listen_thread( .set(0); } Err(ConnectError::Err(e)) => { - error!("Error connecting to {}: {}", domain_name, e); + error!( + timeout=true, success=false, err = ?e, + conn_type="Stun connection", + ); stun_counter_vec_copy .with(&prometheus::labels! {"result" => "err", "domain" => domain_name}) .inc(); @@ -118,7 +132,12 @@ pub fn start_listen_thread( .set(0); } Err(ConnectError::Incomplete) => { - error!("Connection to {} was incomplete", domain_name); + error!( + timeout = true, + success = false, + err = "Incomplete", + conn_type = "Stun connection", + ); stun_counter_vec_copy .with(&prometheus::labels! {"result" => "incomplete", "domain" => domain_name}) .inc(); diff --git a/src/util.rs b/src/util.rs index cab81ec..ed97d58 100644 --- a/src/util.rs +++ b/src/util.rs @@ -17,9 +17,9 @@ use std::net::IpAddr; use std::net::{SocketAddr, ToSocketAddrs}; use gflags; -use log::info; use resolve::config::DnsConfig; use resolve::resolver::DnsResolver; +use tracing::{error, instrument}; gflags::define! { /// Allow IPv6 addresses for domain name lookups. @@ -46,6 +46,7 @@ pub fn resolve_hosts<'a>(servers: &'a Vec<&str>) -> io::Result(servers: &'a Vec<&str>) -> io::Result>> { let mut results = Vec::new(); for name in servers.iter().cloned() { @@ -53,7 +54,7 @@ pub fn resolve_socket_addrs<'a>(servers: &'a Vec<&str>) -> io::Result results.push(addr.into_iter().next()), Err(e) => { - info!("Failed to resolve {} with error {}", name, e); + error!(name, err = ?e, "Failed to resolve"); results.push(None); } }