zaphar/durnitisp
1
0
Fork 0
mirror of https://github.com/zaphar/durnitisp.git synced 2025-07-22 18:19:48 -04:00
Code Issues Packages Projects Releases Wiki Activity

Update to tracing for logs

Browse Source
This commit is contained in:
Jeremy Wall 2022-07-14 21:13:05 -04:00
parent 26ac114f88
commit 2cea3a294e
6 changed files with 230 additions and 160 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

192
Cargo.lock generated
View File

@ -1,5 +1,7 @@
# This file is automatically @generated by Cargo. # This file is automatically @generated by Cargo.
# It is not intended for manual editing. # It is not intended for manual editing.
version = 3
[[package]] [[package]]
name = "aho-corasick" name = "aho-corasick"
version = "0.7.15" version = "0.7.15"
@ -9,6 +11,15 @@ dependencies = [
"memchr", "memchr",
] ]
[[package]]
name = "ansi_term"
version = "0.12.1"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "d52a9bb7ec0cf484c551830a7ce27bd20d67eac647e1befb56b0be4ee39a55d2"
dependencies = [
"winapi",
]
[[package]] [[package]]
name = "anyhow" name = "anyhow"
version = "1.0.38" version = "1.0.38"
@ -27,29 +38,12 @@ version = "1.0.0"
source = "registry+https://github.com/rust-lang/crates.io-index" source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "bbf56136a5198c7b01a49e3afcbef6cf84597273d298f54432926024107b0109" 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]] [[package]]
name = "autocfg" name = "autocfg"
version = "1.0.1" version = "1.0.1"
source = "registry+https://github.com/rust-lang/crates.io-index" source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "cdb031dd78e28731d87d56cc8ffef4a8f36ca26c38fe2de700543e627f8a464a" checksum = "cdb031dd78e28731d87d56cc8ffef4a8f36ca26c38fe2de700543e627f8a464a"
[[package]]
name = "bitflags"
version = "1.2.1"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "cf1de2fe8c75bc145a2f577add951f8134889b4795d47466a54a5c846d691693"
[[package]] [[package]]
name = "byteorder" name = "byteorder"
version = "1.4.2" version = "1.4.2"
@ -98,13 +92,13 @@ dependencies = [
"anyhow", "anyhow",
"gflags", "gflags",
"icmp-socket", "icmp-socket",
"log 0.4.14",
"nursery", "nursery",
"prometheus", "prometheus",
"resolve", "resolve",
"socket2", "socket2",
"stderrlog",
"tiny_http", "tiny_http",
"tracing",
"tracing-subscriber",
] ]
[[package]] [[package]]
@ -296,18 +290,18 @@ dependencies = [
"autocfg", "autocfg",
] ]
[[package]]
name = "numtoa"
version = "0.1.0"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "b8f8bdf33df195859076e54ab11ee78a1b208382d3a26ec40d142ffc1ecc49ef"
[[package]] [[package]]
name = "nursery" name = "nursery"
version = "0.0.1" version = "0.0.1"
source = "registry+https://github.com/rust-lang/crates.io-index" source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "a4bd2d4e0cd7c6bb256afbc59a5921c3ead56f05d7696c92e05b6978858b6fa5" checksum = "a4bd2d4e0cd7c6bb256afbc59a5921c3ead56f05d7696c92e05b6978858b6fa5"
[[package]]
name = "once_cell"
version = "1.13.0"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "18a6dbe30758c9f83eb00cbea4ac95966305f5a7772f3f42ebfc7fc7eddbd8e1"
[[package]] [[package]]
name = "parking_lot" name = "parking_lot"
version = "0.11.1" version = "0.11.1"
@ -328,7 +322,7 @@ dependencies = [
"cfg-if", "cfg-if",
"instant", "instant",
"libc", "libc",
"redox_syscall 0.1.57", "redox_syscall",
"smallvec", "smallvec",
"winapi", "winapi",
] ]
@ -339,6 +333,12 @@ version = "2.1.0"
source = "registry+https://github.com/rust-lang/crates.io-index" source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "d4fd5641d01c8f18a23da7b6fe29298ff4b55afcccdf78973b24cf3175fee32e" checksum = "d4fd5641d01c8f18a23da7b6fe29298ff4b55afcccdf78973b24cf3175fee32e"
[[package]]
name = "pin-project-lite"
version = "0.2.9"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "e0a7ae3ac2f1173085d398531c705756c94a4c56843785df85a60c1a0afac116"
[[package]] [[package]]
name = "proc-macro2" name = "proc-macro2"
version = "1.0.24" version = "1.0.24"
@ -431,24 +431,6 @@ version = "0.1.57"
source = "registry+https://github.com/rust-lang/crates.io-index" source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "41cc0f7e4d5d4544e8861606a285bb08d3e70712ccc7d2b84d7c0ccfaf4b05ce" 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]] [[package]]
name = "ref-cast" name = "ref-cast"
version = "1.0.6" version = "1.0.6"
@ -505,6 +487,15 @@ version = "1.1.0"
source = "registry+https://github.com/rust-lang/crates.io-index" source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "d29ab0c6d3fc0ee92fe66e2d99f700eab17a8d57d1c1d3b748380fb20baa78cd" 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]] [[package]]
name = "smallvec" name = "smallvec"
version = "1.6.1" version = "1.6.1"
@ -522,19 +513,6 @@ dependencies = [
"winapi", "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]] [[package]]
name = "syn" name = "syn"
version = "1.0.60" version = "1.0.60"
@ -546,27 +524,6 @@ dependencies = [
"unicode-xid", "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]] [[package]]
name = "thiserror" name = "thiserror"
version = "1.0.23" version = "1.0.23"
@ -589,11 +546,11 @@ dependencies = [
[[package]] [[package]]
name = "thread_local" name = "thread_local"
version = "1.0.1" version = "1.1.4"
source = "registry+https://github.com/rust-lang/crates.io-index" source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "d40c6d1b69745a6ec6fb1ca717914848da4b44ae29d9b3080cbee91d72a69b14" checksum = "5516c27b78311c50bf42c071425c560ac799b11c30b31f87e3081965fe5e0180"
dependencies = [ dependencies = [
"lazy_static", "once_cell",
] ]
[[package]] [[package]]
@ -635,6 +592,64 @@ version = "0.1.0"
source = "registry+https://github.com/rust-lang/crates.io-index" source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "cda74da7e1a664f795bb1f8a87ec406fb89a02522cf6e50620d016add6dbbf5c" 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]] [[package]]
name = "unicode-bidi" name = "unicode-bidi"
version = "0.3.4" version = "0.3.4"
@ -671,6 +686,12 @@ dependencies = [
"percent-encoding", "percent-encoding",
] ]
[[package]]
name = "valuable"
version = "0.1.0"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "830b7e5d4d90034032940e4ace0d9a9a057e7a45cd94e6c007832e39edb82f6d"
[[package]] [[package]]
name = "wasi" name = "wasi"
version = "0.10.0+wasi-snapshot-preview1" 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" source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "ac3b87c63620426dd9b991e5ce0329eff545bccbbb34f3be09ff6fb6ab51b7b6" 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]] [[package]]
name = "winapi-x86_64-pc-windows-gnu" name = "winapi-x86_64-pc-windows-gnu"
version = "0.4.0" version = "0.4.0"

4
Cargo.toml
View File

@ -7,12 +7,12 @@ edition = "2018"
# See more keys and their definitions at https://doc.rust-lang.org/cargo/reference/manifest.html # See more keys and their definitions at https://doc.rust-lang.org/cargo/reference/manifest.html
[dependencies] [dependencies]
tracing = "0.1.35"
tracing-subscriber = "0.3.14"
anyhow = "1" anyhow = "1"
gflags = "^0.3" gflags = "^0.3"
log = "0.4"
nursery = "^0.0.1" nursery = "^0.0.1"
prometheus = "0.11.0" prometheus = "0.11.0"
stderrlog = "0.5.1"
tiny_http = "0.8.0" tiny_http = "0.8.0"
socket2 = "0.3.19" socket2 = "0.3.19"
icmp-socket = "0.1.1" icmp-socket = "0.1.1"

102
src/icmp.rs
View File

@ -25,9 +25,9 @@ use icmp_socket::{
packet::{Icmpv4Message, Icmpv6Message, WithEchoRequest}, packet::{Icmpv4Message, Icmpv6Message, WithEchoRequest},
IcmpSocket, IcmpSocket4, IcmpSocket6, Icmpv4Packet, Icmpv6Packet, IcmpSocket, IcmpSocket4, IcmpSocket6, Icmpv4Packet, Icmpv6Packet,
}; };
use log::{debug, error, info};
use nursery::{thread, Nursery}; use nursery::{thread, Nursery};
use prometheus::{CounterVec, GaugeVec}; use prometheus::{CounterVec, GaugeVec};
use tracing::{debug, error, info, instrument, warn};
gflags::define! { gflags::define! {
/// The payload to use for the ping requests. /// The payload to use for the ping requests.
@ -87,8 +87,9 @@ impl<'a> PacketHandler<Icmpv6Packet, Ipv6Addr> for &'a mut State<Ipv6Addr> {
return self; return self;
} }
#[instrument(level = "debug", skip(self))]
fn handle_pkt(&mut self, pkt: Icmpv6Packet) -> bool { fn handle_pkt(&mut self, pkt: Icmpv6Packet) -> bool {
debug!("ICMP: handling packet {:?}", pkt); debug!("handling packet");
match pkt.message { match pkt.message {
Icmpv6Message::Unreachable { Icmpv6Message::Unreachable {
_unused, _unused,
@ -115,7 +116,7 @@ impl<'a> PacketHandler<Icmpv6Packet, Ipv6Addr> for &'a mut State<Ipv6Addr> {
} }
Err(e) => { Err(e) => {
// We ignore these as well but log it. // 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 // We ignore these
@ -147,7 +148,7 @@ impl<'a> PacketHandler<Icmpv6Packet, Ipv6Addr> for &'a mut State<Ipv6Addr> {
} }
Err(e) => { Err(e) => {
// We ignore these as well but log it. // 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 // We ignore these
@ -169,16 +170,20 @@ impl<'a> PacketHandler<Icmpv6Packet, Ipv6Addr> for &'a mut State<Ipv6Addr> {
let expected_sequence = *expected_sequence; let expected_sequence = *expected_sequence;
if sequence != expected_sequence { if sequence != expected_sequence {
error!( error!(
"ICMP: Discarding unexpected sequence sequence={} expected={}", sequence,
sequence, expected_sequence expected = expected_sequence,
"Discarding unexpected sequence",
); );
self.time_tracker self.time_tracker
.insert(identifier, (None, expected_sequence.wrapping_add(1))); .insert(identifier, (None, expected_sequence.wrapping_add(1)));
return false; return false;
} }
info!( info!(
"ICMP: Reply from {}({}): time={}ms, seq={}", domain=domain_name,
domain_name, dest, elapsed, sequence, %dest,
time = elapsed,
seq = sequence,
"Reply",
); );
self.ping_counter self.ping_counter
.with(&prometheus::labels! {"result" => "ok", "domain" => domain_name}) .with(&prometheus::labels! {"result" => "ok", "domain" => domain_name})
@ -195,7 +200,7 @@ impl<'a> PacketHandler<Icmpv6Packet, Ipv6Addr> for &'a mut State<Ipv6Addr> {
return false; return false;
}; };
} else { } else {
info!("ICMP: Discarding wrong identifier {}", identifier); warn!(identifier, "Discarding wrong identifier");
} }
} }
_ => { _ => {
@ -211,8 +216,9 @@ impl<'a> PacketHandler<Icmpv4Packet, Ipv4Addr> for &'a mut State<Ipv4Addr> {
return self; return self;
} }
#[instrument(level = "debug", skip(self))]
fn handle_pkt(&mut self, pkt: Icmpv4Packet) -> bool { fn handle_pkt(&mut self, pkt: Icmpv4Packet) -> bool {
debug!("ICMP: handling packet {:?}", pkt); debug!("handling packet");
match pkt.message { match pkt.message {
Icmpv4Message::EchoReply { Icmpv4Message::EchoReply {
identifier, identifier,
@ -228,17 +234,15 @@ impl<'a> PacketHandler<Icmpv4Packet, Ipv4Addr> for &'a mut State<Ipv4Addr> {
let expected_sequence = *expected_sequence; let expected_sequence = *expected_sequence;
if expected_sequence != sequence { if expected_sequence != sequence {
error!( error!(
"ICMP: Discarding unexpected sequence sequence={} expected={}", sequence,
sequence, expected_sequence expected = expected_sequence,
"Discarding unexpected sequence",
); );
self.time_tracker self.time_tracker
.insert(identifier, (None, expected_sequence.wrapping_add(1))); .insert(identifier, (None, expected_sequence.wrapping_add(1)));
return false; return false;
} }
info!( info!(domain=domain_name, %dest, time = elapsed, seq = sequence, "Reply",);
"ICMP: Reply from {}({}): time={}ms, seq={}",
domain_name, dest, elapsed, sequence,
);
self.ping_counter self.ping_counter
.with(&prometheus::labels! {"result" => "ok", "domain" => domain_name}) .with(&prometheus::labels! {"result" => "ok", "domain" => domain_name})
.inc(); .inc();
@ -252,12 +256,12 @@ impl<'a> PacketHandler<Icmpv4Packet, Ipv4Addr> for &'a mut State<Ipv4Addr> {
return false; return false;
}; };
} else { } else {
info!("ICMP: Discarding wrong identifier {}", identifier); info!(identifier, "Discarding wrong identifier");
} }
} }
p => { _ => {
// We ignore the rest. // We ignore the rest.
info!("ICMP Unhandled packet {:?}", p); info!("Unhandled packet");
} }
} }
return false; return false;
@ -287,9 +291,10 @@ where
Sock::AddrType: std::fmt::Display + Copy, Sock::AddrType: std::fmt::Display + Copy,
Sock::PacketType: WithEchoRequest<Packet = Sock::PacketType>, Sock::PacketType: WithEchoRequest<Packet = Sock::PacketType>,
{ {
#[instrument(skip(self, state))]
fn send_all(&mut self, state: &mut State<Sock::AddrType>) -> std::io::Result<()> { fn send_all(&mut self, state: &mut State<Sock::AddrType>) -> std::io::Result<()> {
let destinations = state.destinations.clone(); 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() { for (identifier, (domain_name, dest)) in destinations.into_iter() {
let previous_tracker = state.time_tracker.get(&identifier); let previous_tracker = state.time_tracker.get(&identifier);
let sequence = if previous_tracker.is_some() { let sequence = if previous_tracker.is_some() {
@ -300,8 +305,11 @@ where
let elapsed = Instant::now() - *send_time; let elapsed = Instant::now() - *send_time;
if elapsed > Duration::from_secs(PINGTIMEOUT.flag) { if elapsed > Duration::from_secs(PINGTIMEOUT.flag) {
info!( info!(
"ICMP: Dropped packet detected for domain_name={} send_time={:?} elapsed={:?} sequence={}", domain = domain_name,
domain_name, send_time, elapsed, sequence ?send_time,
?elapsed,
seq = sequence,
"Dropped packet detected",
); );
state.ping_counter state.ping_counter
.with(&prometheus::labels! {"result" => "dropped", "domain" => &domain_name}) .with(&prometheus::labels! {"result" => "dropped", "domain" => &domain_name})
@ -309,8 +317,9 @@ where
sequence.wrapping_add(1) sequence.wrapping_add(1)
} else { } else {
debug!( debug!(
"ICMP: Waiting for timeout before sending next packet domain_name={} sequence={}", domain = domain_name,
domain_name, sequence seq = sequence,
"Waiting for timeout before sending next packet",
); );
continue; continue;
} }
@ -319,14 +328,15 @@ where
} }
} else { } else {
debug!( debug!(
"ICMP: Initializing sequence for first send domain_name={} sequence=0", domain = domain_name,
domain_name seq = 0 as u16,
"Initializing sequence for first send",
); );
0 0
}; };
info!( debug!(
"ICMP: sending echo request to {}({}) sequence={}", domain=domain_name, %dest, sequence,
domain_name, dest, sequence "Sending echo request",
); );
match self.send_to_destination(dest, identifier, sequence) { match self.send_to_destination(dest, identifier, sequence) {
Err(e) => { Err(e) => {
@ -335,9 +345,9 @@ where
.with(&prometheus::labels! {"result" => "err", "type" => "send"}) .with(&prometheus::labels! {"result" => "err", "type" => "send"})
.inc(); .inc();
error!( error!(
"ICMP: error sending to domain: {} and address: {} failed: {:?}, Trying again later", domain=domain_name, %dest, err=?e,
domain_name, &dest, e "Error sending. Trying again later",
); );
} }
Ok(send_time) => { Ok(send_time) => {
state state
@ -346,7 +356,7 @@ where
} }
} }
} }
debug!("ICMP: finished sending for domains"); debug!("Finished sending for domains");
Ok(()) Ok(())
} }
@ -372,6 +382,7 @@ where
Ok(response) Ok(response)
} }
#[instrument(skip(self, handler))]
fn recv_all<H: PacketHandler<Sock::PacketType, Sock::AddrType>>(&mut self, mut handler: H) { fn recv_all<H: PacketHandler<Sock::PacketType, Sock::AddrType>>(&mut self, mut handler: H) {
if handler.get_mut_state().destinations.is_empty() { if handler.get_mut_state().destinations.is_empty() {
debug!("Nothing to send to so skipping for this socket"); debug!("Nothing to send to so skipping for this socket");
@ -394,17 +405,17 @@ where
let loop_start_time = Instant::now(); let loop_start_time = Instant::now();
loop { loop {
// Receive loop // Receive loop
debug!("ICMP: Attempting to recieve packets on socket"); debug!("Attempting to recieve packets on socket");
match self.recv_pkt() { match self.recv_pkt() {
Ok(pkt) => { Ok(pkt) => {
if handler.handle_pkt(pkt) { if handler.handle_pkt(pkt) {
// break out of the recv loop // break out of the recv loop
debug!("ICMP: Recieved Packet"); debug!("Recieved Packet");
return; return;
} }
} }
Err(e) => { Err(e) => {
error!("ICMP: Error receiving packet: {:?}", e); error!(err = ?e, "Error receiving packet");
handler handler
.get_mut_state() .get_mut_state()
.ping_counter .ping_counter
@ -414,7 +425,7 @@ where
} }
} }
if (Instant::now() - loop_start_time) > Duration::from_secs(PINGTIMEOUT.flag) { 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; return;
} }
} }
@ -444,6 +455,7 @@ impl Multi {
} }
} }
#[instrument(name = "ICMP", skip_all)]
pub fn schedule_echo_server( pub fn schedule_echo_server(
domain_names: &Vec<&str>, domain_names: &Vec<&str>,
ping_latency_guage: GaugeVec, ping_latency_guage: GaugeVec,
@ -476,7 +488,11 @@ pub fn schedule_echo_server(
let mut v4_destinations = HashMap::new(); let mut v4_destinations = HashMap::new();
let mut v4_id_counter = 42; let mut v4_id_counter = 42;
for target in v4_targets { 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_destinations.insert(v4_id_counter, target.clone());
v4_id_counter += 1; v4_id_counter += 1;
} }
@ -489,7 +505,11 @@ pub fn schedule_echo_server(
let mut v6_destinations = HashMap::new(); let mut v6_destinations = HashMap::new();
let mut v6_id_counter = 42; let mut v6_id_counter = 42;
for target in v6_targets { 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_destinations.insert(v6_id_counter, target.clone());
v6_id_counter += 1; v6_id_counter += 1;
} }
@ -515,7 +535,7 @@ pub fn schedule_echo_server(
})); }));
let send_multi = multi.clone(); let send_multi = multi.clone();
let send_thread = thread::Pending::new(move || { let send_thread = thread::Pending::new(move || {
info!("ICMP: Starrting send thread"); info!("Starting send thread");
loop { loop {
{ {
send_multi.lock().unwrap().send_all(); send_multi.lock().unwrap().send_all();
@ -524,7 +544,7 @@ pub fn schedule_echo_server(
} }
}); });
let recv_thread = thread::Pending::new(move || { let recv_thread = thread::Pending::new(move || {
info!("ICMP: Starrting recv thread"); info!("Starting recv thread");
loop { loop {
{ {
multi.lock().unwrap().recv_all(); multi.lock().unwrap().recv_all();

50
src/main.rs
View File

@ -11,18 +11,17 @@
// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. // WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
// See the License for the specific language governing permissions and // See the License for the specific language governing permissions and
// limitations under the License. // limitations under the License.
use std::convert::Into; use std::convert::Into;
use std::sync::Arc; use std::sync::Arc;
use gflags; use gflags;
use log::{debug, error, info};
use nursery::thread; use nursery::thread;
use nursery::{Nursery, Waitable}; use nursery::{Nursery, Waitable};
use prometheus::{self, GaugeVec}; use prometheus::{self, GaugeVec};
use prometheus::{CounterVec, Encoder, IntGaugeVec, Opts, Registry, TextEncoder}; use prometheus::{CounterVec, Encoder, IntGaugeVec, Opts, Registry, TextEncoder};
use stderrlog;
use tiny_http; use tiny_http;
use tracing::{debug, error, info, instrument, Level};
use tracing_subscriber::FmtSubscriber;
mod icmp; mod icmp;
mod stun; mod stun;
@ -43,6 +42,11 @@ gflags::define! {
--debug = false --debug = false
} }
gflags::define! {
/// Enable trace logging
--trace = false
}
gflags::define! { gflags::define! {
/// Comma separated list of hosts to ping /// Comma separated list of hosts to ping
--pingHosts = "google.com" --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" --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<()> { fn main() -> anyhow::Result<()> {
gflags::parse(); gflags::parse();
let stun_servers: Vec<&str> = STUNHOSTS.flag.split(",").collect(); let stun_servers: Vec<&str> = STUNHOSTS.flag.split(",").collect();
@ -67,16 +72,24 @@ fn main() -> anyhow::Result<()> {
gflags::print_help_and_exit(0); gflags::print_help_and_exit(0);
} }
let level = if DEBUG.flag || cfg!(debug_assertions) { let subscriber_builder = if DEBUG.flag {
3 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 { } 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() tracing::subscriber::set_global_default(subscriber_builder.finish())
.verbosity(level) .expect("setting default subscriber failed");
.timestamp(stderrlog::Timestamp::Millisecond)
.init()?;
let ping_hosts: Vec<&str> = PINGHOSTS.flag.split(",").collect(); 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. // 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. // thread::Handle starts the thread immediately so the render thread will usually start first.
let render_thread = thread::Handle::new(move || { 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) { let server = match tiny_http::Server::http(LISTENHOST.flag) {
Ok(server) => server, Ok(server) => server,
Err(err) => { Err(err) => {
error!("Error starting render thread {}", err); error!(
error!("Shutting down all threads..."); ?err,
"Error starting render thread. Shutting down all thread.",
);
std::process::exit(1); std::process::exit(1);
} }
}; };
info!("Listening for metrics request on {}", LISTENHOST.flag); info!(
listenthost = LISTENHOST.flag,
"Listening for metrics request on"
);
loop { loop {
info!("Waiting for request"); info!("Waiting for request");
match server.recv() { match server.recv() {
@ -152,11 +170,11 @@ fn main() -> anyhow::Result<()> {
let response = tiny_http::Response::from_data(buffer).with_status_code(200); let response = tiny_http::Response::from_data(buffer).with_status_code(200);
if let Err(e) = req.respond(response) { if let Err(e) = req.respond(response) {
error!("Error responding to request {}", e); error!(err = ?e, "Error responding to request");
} }
} }
Err(e) => { Err(e) => {
info!("Invalid http request! {}", e); error!(err = ?e, "Invalid http request!");
} }
} }
} }

37
src/stun.rs
View File

@ -13,12 +13,12 @@
// limitations under the License. // limitations under the License.
use gflags; use gflags;
use log::{debug, error, info};
use prometheus::{CounterVec, IntGaugeVec}; use prometheus::{CounterVec, IntGaugeVec};
use std::convert::From; use std::convert::From;
use std::io; use std::io;
use std::net::{SocketAddr, UdpSocket}; use std::net::{SocketAddr, UdpSocket};
use std::time::SystemTime; use std::time::SystemTime;
use tracing::{debug, error, info, instrument};
gflags::define! { gflags::define! {
/// Read timeout for the stun server udp receive /// Read timeout for the stun server udp receive
@ -70,6 +70,11 @@ fn attempt_stun_connect(addr: SocketAddr) -> Result<SystemTime, ConnectError> {
Ok(SystemTime::now()) 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( pub fn start_listen_thread(
domain_name: &str, domain_name: &str,
s: SocketAddr, s: SocketAddr,
@ -77,13 +82,18 @@ pub fn start_listen_thread(
stun_latency_vec_copy: IntGaugeVec, stun_latency_vec_copy: IntGaugeVec,
stun_success_vec_copy: IntGaugeVec, stun_success_vec_copy: IntGaugeVec,
) { ) {
debug!("started thread for {}", domain_name); debug!("starting thread");
loop { loop {
let now = SystemTime::now(); let now = SystemTime::now();
info!("Attempting to connect to {}", domain_name); info!("Attempting to connect");
match attempt_stun_connect(s) { match attempt_stun_connect(s) {
Ok(finish_time) => { 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 stun_counter_vec_copy
.with(&prometheus::labels! {"result" => "ok", "domain" => domain_name}) .with(&prometheus::labels! {"result" => "ok", "domain" => domain_name})
.inc(); .inc();
@ -97,9 +107,10 @@ pub fn start_listen_thread(
} }
Err(ConnectError::Timeout(finish_time)) => { Err(ConnectError::Timeout(finish_time)) => {
info!( info!(
"Stun connection to {} timedout after {} millis", timeout = true,
domain_name, success = false,
finish_time.duration_since(now).unwrap().as_millis() millis = finish_time.duration_since(now).unwrap().as_millis(),
conn_type = "Stun connection",
); );
stun_counter_vec_copy stun_counter_vec_copy
.with(&prometheus::labels! {"result" => "timeout", "domain" => domain_name}) .with(&prometheus::labels! {"result" => "timeout", "domain" => domain_name})
@ -109,7 +120,10 @@ pub fn start_listen_thread(
.set(0); .set(0);
} }
Err(ConnectError::Err(e)) => { 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 stun_counter_vec_copy
.with(&prometheus::labels! {"result" => "err", "domain" => domain_name}) .with(&prometheus::labels! {"result" => "err", "domain" => domain_name})
.inc(); .inc();
@ -118,7 +132,12 @@ pub fn start_listen_thread(
.set(0); .set(0);
} }
Err(ConnectError::Incomplete) => { 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 stun_counter_vec_copy
.with(&prometheus::labels! {"result" => "incomplete", "domain" => domain_name}) .with(&prometheus::labels! {"result" => "incomplete", "domain" => domain_name})
.inc(); .inc();

5
src/util.rs
View File

@ -17,9 +17,9 @@ use std::net::IpAddr;
use std::net::{SocketAddr, ToSocketAddrs}; use std::net::{SocketAddr, ToSocketAddrs};
use gflags; use gflags;
use log::info;
use resolve::config::DnsConfig; use resolve::config::DnsConfig;
use resolve::resolver::DnsResolver; use resolve::resolver::DnsResolver;
use tracing::{error, instrument};
gflags::define! { gflags::define! {
/// Allow IPv6 addresses for domain name lookups. /// Allow IPv6 addresses for domain name lookups.
@ -46,6 +46,7 @@ pub fn resolve_hosts<'a>(servers: &'a Vec<&str>) -> io::Result<Vec<Option<IpAddr
return Ok(results); return Ok(results);
} }
#[instrument]
pub fn resolve_socket_addrs<'a>(servers: &'a Vec<&str>) -> io::Result<Vec<Option<SocketAddr>>> { pub fn resolve_socket_addrs<'a>(servers: &'a Vec<&str>) -> io::Result<Vec<Option<SocketAddr>>> {
let mut results = Vec::new(); let mut results = Vec::new();
for name in servers.iter().cloned() { for name in servers.iter().cloned() {
@ -53,7 +54,7 @@ pub fn resolve_socket_addrs<'a>(servers: &'a Vec<&str>) -> io::Result<Vec<Option
match name.to_socket_addrs() { match name.to_socket_addrs() {
Ok(addr) => results.push(addr.into_iter().next()), Ok(addr) => results.push(addr.into_iter().next()),
Err(e) => { Err(e) => {
info!("Failed to resolve {} with error {}", name, e); error!(name, err = ?e, "Failed to resolve");
results.push(None); results.push(None);
} }
} }