diff --git a/Cargo.lock b/Cargo.lock index 9035da81..f8dc7c66 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -782,6 +782,15 @@ version = "0.1.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "ffbee8634e0d45d258acb448e7eaab3fce7a0a467395d4d9f228e3c1f01fb2e4" +[[package]] +name = "matchers" +version = "0.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "8263075bb86c5a1b1427b5ae862e8889656f126e9f77c484496e8b47cf5c5558" +dependencies = [ + "regex-automata", +] + [[package]] name = "matches" version = "0.1.10" @@ -849,6 +858,16 @@ dependencies = [ "static_assertions", ] +[[package]] +name = "nu-ansi-term" +version = "0.46.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "77a8165726e8236064dbb45459242600304b42a5ea24ee2948e18e023bf7ba84" +dependencies = [ + "overload", + "winapi", +] + [[package]] name = "num-integer" version = "0.1.45" @@ -884,6 +903,12 @@ version = "1.17.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "b7e5500299e16ebb147ae15a00a942af264cf3688f47923b8fc2cd5858f23ad3" +[[package]] +name = "overload" +version = "0.1.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "b15813163c1d831bf4a13c3610c05c0d03b39feb07f7e09fa234dac9b15aaf39" + [[package]] name = "parking_lot" version = "0.12.1" @@ -1024,6 +1049,36 @@ dependencies = [ "bitflags", ] +[[package]] +name = "regex" +version = "1.8.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "af83e617f331cc6ae2da5443c602dfa5af81e517212d9d611a5b3ba1777b5370" +dependencies = [ + "regex-syntax 0.7.1", +] + +[[package]] +name = "regex-automata" +version = "0.1.10" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "6c230d73fb8d8c1b9c0b3135c5142a8acee3a0558fb8db5cf1cb65f8d7862132" +dependencies = [ + "regex-syntax 0.6.29", +] + +[[package]] +name = "regex-syntax" +version = "0.6.29" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f162c6dd7b008981e4d40210aca20b4bd0f9b60ca9271061b07f78537722f2e1" + +[[package]] +name = "regex-syntax" +version = "0.7.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "a5996294f19bd3aae0453a862ad728f60e6600695733dd5df01da90c54363a3c" + [[package]] name = "resolv-conf" version = "0.7.0" @@ -1127,6 +1182,15 @@ dependencies = [ "serde", ] +[[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 = "signal-hook" version = "0.3.15" @@ -1322,6 +1386,16 @@ dependencies = [ "syn 2.0.15", ] +[[package]] +name = "thread_local" +version = "1.1.7" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "3fdd6f064ccff2d6567adcb3873ca630700f00b5ad3f060c25b5dcfd9a4ce152" +dependencies = [ + "cfg-if", + "once_cell", +] + [[package]] name = "tinyvec" version = "1.6.0" @@ -1410,6 +1484,17 @@ dependencies = [ "syn 1.0.109", ] +[[package]] +name = "tracing-chrome" +version = "0.7.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "496b3cd5447f7ff527bbbf19b071ad542a000adf297d4127078b4dfdb931f41a" +dependencies = [ + "serde_json", + "tracing-core", + "tracing-subscriber", +] + [[package]] name = "tracing-core" version = "0.1.30" @@ -1417,6 +1502,49 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "24eb03ba0eab1fd845050058ce5e616558e8f8d8fca633e6b163fe25c797213a" 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", + "tracing-core", +] + +[[package]] +name = "tracing-serde" +version = "0.1.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "bc6b213177105856957181934e4920de57730fc69bf42c37ee5bb664d406d9e1" +dependencies = [ + "serde", + "tracing-core", +] + +[[package]] +name = "tracing-subscriber" +version = "0.3.17" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "30a651bc37f915e81f087d86e62a18eec5f79550c7faff886f7090b4ea757c77" +dependencies = [ + "matchers", + "nu-ansi-term", + "once_cell", + "regex", + "serde", + "serde_json", + "sharded-slab", + "smallvec", + "thread_local", + "tracing", + "tracing-core", + "tracing-log", + "tracing-serde", ] [[package]] @@ -1450,6 +1578,9 @@ dependencies = [ "test-case", "thiserror", "toml", + "tracing", + "tracing-chrome", + "tracing-subscriber", "trust-dns-resolver", "tui", "widestring 1.0.2", @@ -1564,6 +1695,12 @@ version = "0.2.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "711b9620af191e0cdc7468a8d14e709c3dcdb115b36f838e601583af800a370a" +[[package]] +name = "valuable" +version = "0.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "830b7e5d4d90034032940e4ace0d9a9a057e7a45cd94e6c007832e39edb82f6d" + [[package]] name = "version_check" version = "0.9.4" diff --git a/Cargo.toml b/Cargo.toml index f1233440..df9a219e 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -24,6 +24,7 @@ thiserror = "1.0.40" derive_more = "0.99.17" arrayvec = "0.7.2" socket2 = { version = "0.5.2", features = [ "all" ] } +tracing = "0.1.37" # TUI dependencies anyhow = "1.0.71" @@ -46,6 +47,8 @@ etcetera = "0.8.0" toml = "0.7.3" indexmap = "1.9.3" maxminddb = "0.23.0" +tracing-subscriber = { version = "0.3.17", features = ["env-filter", "json"] } +tracing-chrome = "0.7.1" # Library dependencies (Linux) [target.'cfg(target_os = "linux")'.dependencies] diff --git a/src/backend.rs b/src/backend.rs index ceff3f5a..412071a2 100644 --- a/src/backend.rs +++ b/src/backend.rs @@ -5,6 +5,7 @@ use parking_lot::RwLock; use std::net::{IpAddr, Ipv4Addr}; use std::sync::Arc; use std::time::Duration; +use tracing::instrument; use trippy::tracing::{ Probe, ProbeStatus, Tracer, TracerChannel, TracerChannelConfig, TracerConfig, TracerRound, }; @@ -266,6 +267,7 @@ impl Default for Hop { /// /// Note that this implementation blocks the tracer on the `RwLock` and so any delays in the the TUI will delay the /// next round of the started. +#[instrument(skip_all)] pub fn run_backend( tracer_config: &TracerConfig, channel_config: &TracerChannelConfig, diff --git a/src/config.rs b/src/config.rs index 88a7b131..d984930f 100644 --- a/src/config.rs +++ b/src/config.rs @@ -47,6 +47,15 @@ const MAX_GRACE_DURATION_MS: Duration = Duration::from_millis(1000); /// The default value for `mode`. const DEFAULT_MODE: Mode = Mode::Tui; +/// The default value for `log-format`. +const DEFAULT_LOG_FORMAT: LogFormat = LogFormat::Pretty; + +/// The default value for `log-span-events`. +const DEFAULT_LOG_SPAN_EVENTS: LogSpanEvents = LogSpanEvents::Off; + +/// The default value for `log-filter`. +const DEFAULT_LOG_FILTER: &str = "trippy=debug"; + /// The default value for `protocol`. const DEFAULT_STRATEGY_PROTOCOL: Protocol = Protocol::Icmp; @@ -248,6 +257,32 @@ pub enum DnsResolveMethod { Cloudflare, } +/// How to format log data. +#[derive(Debug, Copy, Clone, ValueEnum, Deserialize)] +#[serde(rename_all = "kebab-case")] +pub enum LogFormat { + /// Display log data in a compact format. + Compact, + /// Display log data in a pretty format. + Pretty, + /// Display log data in a json format. + Json, + /// Display log data in Chrome trace format. + Chrome, +} + +/// How to log event spans. +#[derive(Debug, Copy, Clone, ValueEnum, Deserialize)] +#[serde(rename_all = "kebab-case")] +pub enum LogSpanEvents { + /// Do not display event spans. + Off, + /// Display enter and exit event spans. + Active, + /// Display all event spans. + Full, +} + /// Trace a route to a host and record statistics #[derive(Parser, Debug)] #[command(name = "trip", author, version, about, long_about = None)] @@ -425,6 +460,22 @@ pub struct Args { /// Generate shell completion #[arg(long, display_order = 39)] pub generate: Option, + + /// The debug log format [default: pretty] + #[arg(long, display_order = 40)] + pub log_format: Option, + + /// The debug log filter [default: trippy=debug] + #[arg(long, display_order = 41)] + pub log_filter: Option, + + /// The debug log format [default: off] + #[arg(long, display_order = 42)] + pub log_span_events: Option, + + /// Enable verbose debug logging + #[arg(short = 'v', long, default_value_t = false, display_order = 43)] + pub verbose: bool, } fn parse_tui_theme_color_value(value: &str) -> anyhow::Result<(TuiThemeItem, TuiColor)> { @@ -481,6 +532,10 @@ pub struct TrippyConfig { pub report_cycles: usize, pub geoip_mmdb_file: Option, pub max_rounds: Option, + pub verbose: bool, + pub log_format: LogFormat, + pub log_filter: String, + pub log_span_events: LogSpanEvents, } /// Tui color theme. @@ -1270,8 +1325,8 @@ pub enum TuiCommandItem { pub mod config_file { use crate::config::{ - AddressFamily, AddressMode, AsMode, DnsResolveMethod, GeoIpMode, Mode, - MultipathStrategyConfig, Protocol, TuiColor, TuiKeyBinding, + AddressFamily, AddressMode, AsMode, DnsResolveMethod, GeoIpMode, LogFormat, LogSpanEvents, + Mode, MultipathStrategyConfig, Protocol, TuiColor, TuiKeyBinding, }; use anyhow::Context; use etcetera::BaseStrategy; @@ -1354,6 +1409,9 @@ pub mod config_file { #[serde(rename_all = "kebab-case", deny_unknown_fields)] pub struct ConfigTrippy { pub mode: Option, + pub log_format: Option, + pub log_filter: Option, + pub log_span_events: Option, } #[derive(Debug, Default, Deserialize)] @@ -1510,6 +1568,22 @@ impl TryFrom<(Args, u16)> for TrippyConfig { let cfg_file_dns = cfg_file.dns.unwrap_or_default(); let cfg_file_report = cfg_file.report.unwrap_or_default(); let mode = cfg_layer(args.mode, cfg_file_trace.mode, DEFAULT_MODE); + let verbose = args.verbose; + let log_format = cfg_layer( + args.log_format, + cfg_file_trace.log_format, + DEFAULT_LOG_FORMAT, + ); + let log_filter = cfg_layer( + args.log_filter, + cfg_file_trace.log_filter, + String::from(DEFAULT_LOG_FILTER), + ); + let log_span_events = cfg_layer( + args.log_span_events, + cfg_file_trace.log_span_events, + DEFAULT_LOG_SPAN_EVENTS, + ); let protocol = cfg_layer( args.protocol, cfg_file_strategy.protocol, @@ -1701,6 +1775,7 @@ impl TryFrom<(Args, u16)> for TrippyConfig { Some(n) if n > 0 => Some(n), _ => None, }; + validate_logging(mode, verbose)?; validate_multi(mode, protocol, &args.targets)?; validate_ttl(first_ttl, max_ttl)?; validate_max_inflight(max_inflight)?; @@ -1758,6 +1833,10 @@ impl TryFrom<(Args, u16)> for TrippyConfig { report_cycles, geoip_mmdb_file, max_rounds, + verbose, + log_format, + log_filter, + log_span_events, }) } } @@ -1780,6 +1859,14 @@ fn cfg_layer_opt(fst: Option, snd: Option) -> Option { } } +fn validate_logging(mode: Mode, verbose: bool) -> anyhow::Result<()> { + if matches!(mode, Mode::Tui) && verbose { + Err(anyhow!("cannot enable verbose logging in tui mode")) + } else { + Ok(()) + } +} + /// We only allow multiple targets to be specified for the Tui and for `Icmp` tracing. fn validate_multi(mode: Mode, protocol: TracerProtocol, targets: &[String]) -> anyhow::Result<()> { match (mode, protocol) { diff --git a/src/main.rs b/src/main.rs index 5f9f8695..372e803c 100644 --- a/src/main.rs +++ b/src/main.rs @@ -14,7 +14,7 @@ #![deny(unsafe_code)] use crate::backend::Trace; use crate::caps::{drop_caps, ensure_caps}; -use crate::config::{Mode, TrippyConfig}; +use crate::config::{LogFormat, LogSpanEvents, Mode, TrippyConfig}; use crate::dns::{DnsResolver, DnsResolverConfig}; use crate::frontend::TuiConfig; use crate::geoip::GeoIpLookup; @@ -26,6 +26,10 @@ use std::net::IpAddr; use std::sync::Arc; use std::thread; use std::time::Duration; +use tracing_chrome::{ChromeLayerBuilder, FlushGuard}; +use tracing_subscriber::fmt::format::FmtSpan; +use tracing_subscriber::layer::SubscriberExt; +use tracing_subscriber::util::SubscriberInitExt; use trippy::tracing::SourceAddr; use trippy::tracing::{ MultipathStrategy, PortDirection, TracerAddrFamily, TracerChannelConfig, TracerConfig, @@ -43,6 +47,7 @@ mod report; fn main() -> anyhow::Result<()> { let pid = u16::try_from(std::process::id() % u32::from(u16::MAX))?; let cfg = TrippyConfig::try_from((Args::parse(), pid))?; + let _guard = configure_logging(&cfg); let resolver = start_dns_resolver(&cfg)?; let geoip_lookup = create_geoip_lookup(&cfg)?; ensure_caps()?; @@ -79,6 +84,48 @@ fn create_geoip_lookup(cfg: &TrippyConfig) -> anyhow::Result { } } +fn configure_logging(cfg: &TrippyConfig) -> Option { + if cfg.verbose { + let fmt_span = match cfg.log_span_events { + LogSpanEvents::Off => FmtSpan::NONE, + LogSpanEvents::Active => FmtSpan::ACTIVE, + LogSpanEvents::Full => FmtSpan::FULL, + }; + match cfg.log_format { + LogFormat::Compact => { + tracing_subscriber::fmt() + .with_span_events(fmt_span) + .with_env_filter(&cfg.log_filter) + .compact() + .init(); + } + LogFormat::Pretty => { + tracing_subscriber::fmt() + .with_span_events(fmt_span) + .with_env_filter(&cfg.log_filter) + .pretty() + .init(); + } + LogFormat::Json => { + tracing_subscriber::fmt() + .with_span_events(fmt_span) + .with_env_filter(&cfg.log_filter) + .json() + .init(); + } + LogFormat::Chrome => { + let (chrome_layer, guard) = ChromeLayerBuilder::new() + .writer(std::io::stdout()) + .include_args(true) + .build(); + tracing_subscriber::registry().with(chrome_layer).init(); + return Some(guard); + } + } + } + None +} + /// Start a tracer to a given target. fn start_tracer( cfg: &TrippyConfig, diff --git a/src/tracing/net/channel.rs b/src/tracing/net/channel.rs index 8f6c9d46..74d9527a 100644 --- a/src/tracing/net/channel.rs +++ b/src/tracing/net/channel.rs @@ -9,6 +9,7 @@ use arrayvec::ArrayVec; use itertools::Itertools; use std::net::IpAddr; use std::time::{Duration, SystemTime}; +use tracing::instrument; /// The maximum size of the IP packet we allow. pub const MAX_PACKET_SIZE: usize = 1024; @@ -38,7 +39,9 @@ impl TracerChannel { /// Create an `IcmpChannel`. /// /// This operation requires the `CAP_NET_RAW` capability on Linux. + #[instrument(skip_all)] pub fn connect(config: &TracerChannelConfig) -> TraceResult { + tracing::debug!(?config); if usize::from(config.packet_size.0) > MAX_PACKET_SIZE { return Err(TracerError::InvalidPacketSize(usize::from( config.packet_size.0, @@ -70,6 +73,7 @@ impl TracerChannel { } impl Network for TracerChannel { + #[instrument(skip(self))] fn send_probe(&mut self, probe: Probe) -> TraceResult<()> { match self.protocol { TracerProtocol::Icmp => self.dispatch_icmp_probe(probe), @@ -77,20 +81,25 @@ impl Network for TracerChannel { TracerProtocol::Tcp => self.dispatch_tcp_probe(probe), } } - + #[instrument(skip_all)] fn recv_probe(&mut self) -> TraceResult> { - match self.protocol { + let prob_response = match self.protocol { TracerProtocol::Icmp | TracerProtocol::Udp => self.recv_icmp_probe(), TracerProtocol::Tcp => match self.recv_tcp_sockets()? { None => self.recv_icmp_probe(), resp => Ok(resp), }, + }?; + if let Some(resp) = prob_response { + tracing::debug!(?resp); } + Ok(prob_response) } } impl TracerChannel { /// Dispatch a ICMP probe. + #[instrument(skip_all)] fn dispatch_icmp_probe(&mut self, probe: Probe) -> TraceResult<()> { match (self.src_addr, self.dest_addr) { (IpAddr::V4(src_addr), IpAddr::V4(dest_addr)) => ipv4::dispatch_icmp_probe( @@ -115,6 +124,7 @@ impl TracerChannel { } /// Dispatch a UDP probe. + #[instrument(skip_all)] fn dispatch_udp_probe(&mut self, probe: Probe) -> TraceResult<()> { match (self.src_addr, self.dest_addr) { (IpAddr::V4(src_addr), IpAddr::V4(dest_addr)) => ipv4::dispatch_udp_probe( @@ -140,6 +150,7 @@ impl TracerChannel { } /// Dispatch a TCP probe. + #[instrument(skip_all)] fn dispatch_tcp_probe(&mut self, probe: Probe) -> TraceResult<()> { let socket = match (self.src_addr, self.dest_addr) { (IpAddr::V4(src_addr), IpAddr::V4(dest_addr)) => { @@ -156,6 +167,7 @@ impl TracerChannel { } /// Generate a `ProbeResponse` for the next available ICMP packet, if any + #[instrument(skip(self))] fn recv_icmp_probe(&mut self) -> TraceResult> { if self.recv_socket.is_readable(self.read_timeout)? { match self.dest_addr { @@ -170,6 +182,7 @@ impl TracerChannel { /// Generate synthetic `ProbeResponse` if a TCP socket is connected or if the connection was refused. /// /// Any TCP socket which has not connected or failed after a timeout will be removed. + #[instrument(skip(self))] fn recv_tcp_sockets(&mut self) -> TraceResult> { self.tcp_probes .retain(|probe| probe.start.elapsed().unwrap_or_default() < self.tcp_connect_timeout); @@ -212,6 +225,7 @@ impl TcpProbe { } /// Make a socket for sending raw `ICMP` packets. +#[instrument] fn make_icmp_send_socket(addr: IpAddr) -> TraceResult { Ok(match addr { IpAddr::V4(_) => Socket::new_icmp_send_socket_ipv4(), @@ -220,6 +234,7 @@ fn make_icmp_send_socket(addr: IpAddr) -> TraceResult { } /// Make a socket for sending `UDP` packets. +#[instrument] fn make_udp_send_socket(addr: IpAddr) -> TraceResult { Ok(match addr { IpAddr::V4(_) => Socket::new_udp_send_socket_ipv4(), @@ -228,6 +243,7 @@ fn make_udp_send_socket(addr: IpAddr) -> TraceResult { } /// Make a socket for receiving raw `ICMP` packets. +#[instrument] fn make_recv_socket(addr: IpAddr) -> TraceResult { Ok(match addr { IpAddr::V4(ipv4addr) => Socket::new_recv_socket_ipv4(ipv4addr), diff --git a/src/tracing/net/ipv4.rs b/src/tracing/net/ipv4.rs index 27a151e9..bb3f201a 100644 --- a/src/tracing/net/ipv4.rs +++ b/src/tracing/net/ipv4.rs @@ -24,6 +24,7 @@ use crate::tracing::{MultipathStrategy, Probe, TracerProtocol}; use std::io::ErrorKind; use std::net::{IpAddr, Ipv4Addr, SocketAddr}; use std::time::SystemTime; +use tracing::instrument; /// The maximum size of UDP packet we allow. const MAX_UDP_PACKET_BUF: usize = MAX_PACKET_SIZE - Ipv4Packet::minimum_packet_size(); @@ -43,6 +44,7 @@ const MAX_ICMP_PAYLOAD_BUF: usize = MAX_ICMP_PACKET_BUF - IcmpPacket::minimum_pa const DONT_FRAGMENT: u16 = 0x4000; #[allow(clippy::too_many_arguments)] +#[instrument(skip(icmp_send_socket, probe))] pub fn dispatch_icmp_probe( icmp_send_socket: &mut Socket, probe: Probe, @@ -81,6 +83,7 @@ pub fn dispatch_icmp_probe( } #[allow(clippy::too_many_arguments)] +#[instrument(skip(raw_send_socket, probe))] pub fn dispatch_udp_probe( raw_send_socket: &mut Socket, probe: Probe, @@ -142,6 +145,7 @@ fn swap_checksum_and_payload(udp: &mut UdpPacket<'_>) { udp.set_payload(&checksum); } +#[instrument(skip(probe))] pub fn dispatch_tcp_probe( probe: Probe, src_addr: Ipv4Addr, @@ -179,6 +183,7 @@ pub fn dispatch_tcp_probe( Ok(socket) } +#[instrument(skip(recv_socket))] pub fn recv_icmp_probe( recv_socket: &mut Socket, protocol: TracerProtocol, @@ -196,6 +201,7 @@ pub fn recv_icmp_probe( } } +#[instrument(skip(tcp_socket))] pub fn recv_tcp_socket( tcp_socket: &Socket, sequence: Sequence, @@ -315,6 +321,7 @@ fn udp_payload_size(packet_size: usize) -> usize { packet_size - udp_header_size - ip_header_size } +#[instrument] fn extract_probe_resp( protocol: TracerProtocol, ipv4: &Ipv4Packet<'_>, @@ -353,6 +360,7 @@ fn extract_probe_resp( }) } +#[instrument] fn extract_time_exceeded( packet: &TimeExceededPacket<'_>, protocol: TracerProtocol, @@ -379,6 +387,7 @@ fn extract_time_exceeded( }) } +#[instrument] fn extract_dest_unreachable( packet: &DestinationUnreachablePacket<'_>, protocol: TracerProtocol, @@ -403,6 +412,7 @@ fn extract_dest_unreachable( }) } +#[instrument] fn extract_echo_request(payload: &[u8]) -> TraceResult> { let ip4 = Ipv4Packet::new_view(payload).req()?; let header_len = usize::from(ip4.get_header_length() * 4); @@ -412,6 +422,7 @@ fn extract_echo_request(payload: &[u8]) -> TraceResult> { } /// Get the src and dest ports from the original `UdpPacket` packet embedded in the payload. +#[instrument] fn extract_udp_packet(payload: &[u8]) -> TraceResult<(u16, u16, u16, u16)> { let ip4 = Ipv4Packet::new_view(payload).req()?; let header_len = usize::from(ip4.get_header_length() * 4); @@ -435,6 +446,7 @@ fn extract_udp_packet(payload: &[u8]) -> TraceResult<(u16, u16, u16, u16)> { /// /// We therefore have to detect this situation and ensure we provide buffer a large enough for a complete TCP packet /// header. +#[instrument] fn extract_tcp_packet(payload: &[u8]) -> TraceResult<(u16, u16)> { let ip4 = Ipv4Packet::new_view(payload).req()?; let header_len = usize::from(ip4.get_header_length() * 4); diff --git a/src/tracing/net/ipv6.rs b/src/tracing/net/ipv6.rs index e15835cb..9336a6d3 100644 --- a/src/tracing/net/ipv6.rs +++ b/src/tracing/net/ipv6.rs @@ -23,6 +23,7 @@ use crate::tracing::{Probe, TracerProtocol}; use std::io::ErrorKind; use std::net::{IpAddr, Ipv6Addr, SocketAddr}; use std::time::SystemTime; +use tracing::instrument; /// The maximum size of UDP packet we allow. const MAX_UDP_PACKET_BUF: usize = MAX_PACKET_SIZE - Ipv6Packet::minimum_packet_size(); @@ -36,6 +37,7 @@ const MAX_ICMP_PACKET_BUF: usize = MAX_PACKET_SIZE - Ipv6Packet::minimum_packet_ /// The maximum size of ICMP payload we allow. const MAX_ICMP_PAYLOAD_BUF: usize = MAX_ICMP_PACKET_BUF - IcmpPacket::minimum_packet_size(); +#[instrument(skip(icmp_send_socket, probe))] pub fn dispatch_icmp_probe( icmp_send_socket: &mut Socket, probe: Probe, @@ -65,6 +67,7 @@ pub fn dispatch_icmp_probe( } #[allow(clippy::too_many_arguments)] +#[instrument(skip(udp_send_socket, probe))] pub fn dispatch_udp_probe( udp_send_socket: &mut Socket, probe: Probe, @@ -95,6 +98,7 @@ pub fn dispatch_udp_probe( Ok(()) } +#[instrument(skip(probe))] pub fn dispatch_tcp_probe( probe: Probe, src_addr: Ipv6Addr, @@ -130,6 +134,7 @@ pub fn dispatch_tcp_probe( Ok(socket) } +#[instrument(skip(recv_socket))] pub fn recv_icmp_probe( recv_socket: &mut Socket, protocol: TracerProtocol, @@ -153,6 +158,7 @@ pub fn recv_icmp_probe( } } +#[instrument(skip(tcp_socket))] pub fn recv_tcp_socket( tcp_socket: &Socket, sequence: Sequence, diff --git a/src/tracing/net/platform/unix.rs b/src/tracing/net/platform/unix.rs index 6779d00b..076ac7e5 100644 --- a/src/tracing/net/platform/unix.rs +++ b/src/tracing/net/platform/unix.rs @@ -2,6 +2,7 @@ use super::byte_order::PlatformIpv4FieldByteOrder; use crate::tracing::error::{TraceResult, TracerError}; use crate::tracing::net::socket::TracerSocket; use crate::tracing::util::Required; +use itertools::Itertools; use nix::{ sys::select::FdSet, sys::socket::{AddressFamily, SockaddrLike}, @@ -14,6 +15,7 @@ use std::net::{IpAddr, Ipv4Addr, Ipv6Addr}; use std::net::{Shutdown, SocketAddr}; use std::os::unix::io::AsRawFd; use std::time::Duration; +use tracing::instrument; /// The size of the test packet to use for discovering the `total_length` byte order. #[cfg(not(target_os = "linux"))] @@ -30,6 +32,7 @@ pub fn for_address(_src_addr: IpAddr) -> TraceResult } #[cfg(not(target_os = "linux"))] +#[instrument(ret)] pub fn for_address(addr: IpAddr) -> TraceResult { let addr = match addr { IpAddr::V4(addr) => addr, @@ -52,6 +55,7 @@ pub fn for_address(addr: IpAddr) -> TraceResult { /// The packet is actually of length `256` bytes but we set the `total_length` based on the input provided so as to /// test if the OS rejects the attempt. #[cfg(not(target_os = "linux"))] +#[instrument(ret)] fn test_send_local_ip4_packet(src_addr: Ipv4Addr, total_length: u16) -> TraceResult<()> { let mut buf = [0_u8; TEST_PACKET_LENGTH as usize]; let mut ipv4 = crate::tracing::packet::ipv4::Ipv4Packet::new(&mut buf).req()?; @@ -73,6 +77,7 @@ fn test_send_local_ip4_packet(src_addr: Ipv4Addr, total_length: u16) -> TraceRes Ok(()) } +#[instrument(ret)] pub fn lookup_interface_addr_ipv4(name: &str) -> TraceResult { nix::ifaddrs::getifaddrs() .map_err(|_| TracerError::UnknownInterface(name.to_string()))? @@ -87,6 +92,7 @@ pub fn lookup_interface_addr_ipv4(name: &str) -> TraceResult { .ok_or_else(|| TracerError::UnknownInterface(name.to_string())) } +#[instrument(ret)] pub fn lookup_interface_addr_ipv6(name: &str) -> TraceResult { nix::ifaddrs::getifaddrs() .map_err(|_| TracerError::UnknownInterface(name.to_string()))? @@ -102,6 +108,7 @@ pub fn lookup_interface_addr_ipv6(name: &str) -> TraceResult { } #[allow(clippy::unnecessary_wraps)] +#[instrument] pub fn startup() -> TraceResult<()> { Ok(()) } @@ -122,6 +129,7 @@ pub fn is_host_unreachable_error(_code: i32) -> bool { /// Discover the local `IpAddr` that will be used to communicate with the given target `IpAddr`. /// /// Note that no packets are transmitted by this method. +#[instrument(ret)] pub fn discover_local_addr(target_addr: IpAddr, port: u16) -> TraceResult { let socket = match target_addr { IpAddr::V4(_) => Socket::new_udp_dgram_socket_ipv4(), @@ -165,82 +173,103 @@ impl Socket { } impl TracerSocket for Socket { + #[instrument] fn new_icmp_send_socket_ipv4() -> io::Result { let socket = Self::new_raw_ipv4(Protocol::from(nix::libc::IPPROTO_RAW))?; socket.set_nonblocking(true)?; socket.set_header_included(true)?; Ok(socket) } + #[instrument] fn new_icmp_send_socket_ipv6() -> io::Result { let socket = Self::new_raw_ipv6(Protocol::ICMPV6)?; socket.set_nonblocking(true)?; Ok(socket) } + #[instrument] fn new_udp_send_socket_ipv4() -> io::Result { let socket = Self::new_raw_ipv4(Protocol::from(nix::libc::IPPROTO_RAW))?; socket.set_nonblocking(true)?; socket.set_header_included(true)?; Ok(socket) } + #[instrument] fn new_udp_send_socket_ipv6() -> io::Result { let socket = Self::new_raw_ipv6(Protocol::UDP)?; socket.set_nonblocking(true)?; Ok(socket) } - fn new_recv_socket_ipv4(_addr: Ipv4Addr) -> io::Result { + #[instrument] + fn new_recv_socket_ipv4(addr: Ipv4Addr) -> io::Result { let socket = Self::new_raw_ipv4(Protocol::ICMPV4)?; socket.set_nonblocking(true)?; socket.set_header_included(true)?; Ok(socket) } - fn new_recv_socket_ipv6(_addr: Ipv6Addr) -> io::Result { + #[instrument] + fn new_recv_socket_ipv6(addr: Ipv6Addr) -> io::Result { let socket = Self::new_raw_ipv6(Protocol::ICMPV6)?; socket.set_nonblocking(true)?; Ok(socket) } + #[instrument] fn new_stream_socket_ipv4() -> io::Result { let socket = Self::new(Domain::IPV4, Type::STREAM, Protocol::TCP)?; socket.set_nonblocking(true)?; socket.set_reuse_port(true)?; Ok(socket) } + #[instrument] fn new_stream_socket_ipv6() -> io::Result { let socket = Self::new(Domain::IPV6, Type::STREAM, Protocol::TCP)?; socket.set_nonblocking(true)?; socket.set_reuse_port(true)?; Ok(socket) } + #[instrument] fn new_udp_dgram_socket_ipv4() -> io::Result { Self::new(Domain::IPV4, Type::DGRAM, Protocol::UDP) } + #[instrument] fn new_udp_dgram_socket_ipv6() -> io::Result { Self::new(Domain::IPV6, Type::DGRAM, Protocol::UDP) } + #[instrument(skip(self))] fn bind(&mut self, address: SocketAddr) -> io::Result<()> { self.inner.bind(&SockAddr::from(address)) } + #[instrument(skip(self))] fn set_tos(&self, tos: u32) -> io::Result<()> { self.inner.set_tos(tos) } + #[instrument(skip(self))] fn set_ttl(&self, ttl: u32) -> io::Result<()> { self.inner.set_ttl(ttl) } + #[instrument(skip(self))] fn set_reuse_port(&self, reuse: bool) -> io::Result<()> { self.inner.set_reuse_port(reuse) } + #[instrument(skip(self))] fn set_header_included(&self, included: bool) -> io::Result<()> { self.inner.set_header_included(included) } + #[instrument(skip(self))] fn set_unicast_hops_v6(&self, hops: u8) -> io::Result<()> { self.inner.set_unicast_hops_v6(u32::from(hops)) } + #[instrument(skip(self))] fn connect(&self, address: SocketAddr) -> io::Result<()> { + tracing::debug!(?address); self.inner.connect(&SockAddr::from(address)) } + #[instrument(skip(self, buf))] fn send_to(&self, buf: &[u8], addr: SocketAddr) -> io::Result<()> { + tracing::debug!(buf = format!("{:02x?}", buf.iter().format(" ")), ?addr); self.inner.send_to(buf, &SockAddr::from(addr))?; Ok(()) } + #[instrument(skip(self))] fn is_readable(&self, timeout: Duration) -> io::Result { let mut read = FdSet::new(); read.insert(self.inner.as_raw_fd()); @@ -253,6 +282,7 @@ impl TracerSocket for Socket { )?; Ok(readable == 1) } + #[instrument(skip(self))] fn is_writable(&self) -> io::Result { let mut write = FdSet::new(); write.insert(self.inner.as_raw_fd()); @@ -265,26 +295,46 @@ impl TracerSocket for Socket { )?; Ok(writable == 1) } + #[instrument(skip(self, buf), ret)] fn recv_from(&mut self, buf: &mut [u8]) -> io::Result<(usize, Option)> { - self.inner.recv_from_into_buf(buf) - } + let (bytes_read, addr) = self.inner.recv_from_into_buf(buf)?; + tracing::debug!( + buf = format!("{:02x?}", buf[..bytes_read].iter().format(" ")), + bytes_read, + ?addr + ); + Ok((bytes_read, addr)) + } + #[instrument(skip(self, buf), ret)] fn read(&mut self, buf: &mut [u8]) -> io::Result { - self.inner.read(buf) - } + let bytes_read = self.inner.read(buf)?; + tracing::debug!( + buf = format!("{:02x?}", buf[..bytes_read].iter().format(" ")), + bytes_read + ); + Ok(bytes_read) + } + #[instrument(skip(self))] fn shutdown(&self) -> io::Result<()> { self.inner.shutdown(Shutdown::Both) } + #[instrument(skip(self), ret)] fn peer_addr(&self) -> io::Result> { - Ok(self.inner.peer_addr()?.as_socket()) + let addr = self.inner.peer_addr()?.as_socket(); + tracing::debug!(?addr); + Ok(addr) } + #[instrument(skip(self), ret)] fn take_error(&self) -> io::Result> { self.inner.take_error() } #[allow(clippy::unused_self, clippy::unnecessary_wraps)] + #[instrument(skip(self), ret)] fn icmp_error_info(&self) -> io::Result { Ok(IpAddr::V4(Ipv4Addr::UNSPECIFIED)) } #[allow(clippy::unused_self, clippy::unnecessary_wraps)] + #[instrument(skip(self))] fn close(&self) -> io::Result<()> { Ok(()) } diff --git a/src/tracing/net/platform/windows.rs b/src/tracing/net/platform/windows.rs index 98ddb3eb..179d8d19 100644 --- a/src/tracing/net/platform/windows.rs +++ b/src/tracing/net/platform/windows.rs @@ -11,6 +11,7 @@ use std::net::{IpAddr, Ipv4Addr, Ipv6Addr, SocketAddr, SocketAddrV4, SocketAddrV use std::os::windows::prelude::AsRawSocket; use std::ptr::{addr_of, addr_of_mut, null_mut}; use std::time::Duration; +use tracing::instrument; use windows_sys::Win32::Foundation::{WAIT_FAILED, WAIT_TIMEOUT}; use windows_sys::Win32::Networking::WinSock::{ AF_INET, AF_INET6, FD_CONNECT, FD_WRITE, ICMP_ERROR_INFO, IN6_ADDR, IN6_ADDR_0, IN_ADDR, @@ -63,18 +64,22 @@ pub fn for_address(_src_addr: IpAddr) -> TraceResult Ok(PlatformIpv4FieldByteOrder::Network) } +#[instrument(ret)] pub fn lookup_interface_addr_ipv4(name: &str) -> TraceResult { lookup_interface_addr(&Adapters::ipv4()?, name) } +#[instrument(ret)] pub fn lookup_interface_addr_ipv6(name: &str) -> TraceResult { lookup_interface_addr(&Adapters::ipv6()?, name) } +#[instrument(skip(_port), ret)] pub fn discover_local_addr(target: IpAddr, _port: u16) -> TraceResult { routing_interface_query(target) } +#[instrument] pub fn startup() -> Result<()> { Socket::startup() } @@ -128,11 +133,13 @@ impl Socket { }) } + #[instrument(skip(self))] fn create_event(&mut self) -> Result<()> { self.ol.hEvent = syscall!(WSACreateEvent(), |res| { res == 0 || res == -1 })?; Ok(()) } + #[instrument(skip(self))] fn wait_for_event(&self, timeout: Duration) -> Result { let millis = timeout.as_millis() as u32; let rc = syscall_threading!(WaitForSingleObject(self.ol.hEvent, millis)); @@ -144,10 +151,12 @@ impl Socket { Ok(true) } + #[instrument(skip(self))] fn reset_event(&self) -> Result<()> { syscall!(WSAResetEvent(self.ol.hEvent), |res| { res == 0 }).map(|_| ()) } + #[instrument(skip(self, optval))] fn getsockopt(&self, level: i32, optname: i32, mut optval: T) -> Result { let mut optlen = size_of::() as i32; syscall!( @@ -163,6 +172,7 @@ impl Socket { Ok(optval) } + #[instrument(skip(self))] fn setsockopt_u32(&self, level: i32, optname: i32, optval: u32) -> Result<()> { let bytes = optval.to_ne_bytes(); let optval = addr_of!(bytes).cast(); @@ -179,19 +189,23 @@ impl Socket { .map(|_| ()) } + #[instrument(skip(self))] fn setsockopt_bool(&self, level: i32, optname: i32, optval: bool) -> Result<()> { self.setsockopt_u32(level, optname, u32::from(optval)) } + #[instrument(skip(self))] fn set_fail_connect_on_icmp_error(&self, enabled: bool) -> Result<()> { self.setsockopt_bool(IPPROTO_TCP, TCP_FAIL_CONNECT_ON_ICMP_ERROR as _, enabled) } + #[instrument(skip(self))] fn set_non_blocking(&self, is_non_blocking: bool) -> Result<()> { self.inner.set_nonblocking(is_non_blocking) } // TODO handle case where `WSARecvFrom` succeeded immediately. + #[instrument(skip(self))] fn post_recv_from(&mut self) -> Result<()> { fn is_err(res: i32) -> bool { res == SOCKET_ERROR && Error::last_os_error().raw_os_error() != Some(WSA_IO_PENDING) @@ -218,6 +232,7 @@ impl Socket { Ok(()) } + #[instrument(skip(self))] fn get_overlapped_result(&self) -> Result<(u32, u32)> { let mut bytes = 0; let mut flags = 0; @@ -271,20 +286,22 @@ impl Drop for Socket { #[allow(clippy::cast_possible_wrap)] impl TracerSocket for Socket { + #[instrument] fn new_icmp_send_socket_ipv4() -> Result { - // let sock = Self::new(AF_INET, SOCK_RAW, IPPROTO_RAW)?; let sock = Self::new(Domain::IPV4, Type::RAW, Some(Protocol::from(IPPROTO_RAW)))?; sock.set_non_blocking(true)?; sock.set_header_included(true)?; Ok(sock) } + #[instrument] fn new_icmp_send_socket_ipv6() -> Result { let sock = Self::new(Domain::IPV6, Type::RAW, Some(Protocol::ICMPV6))?; sock.set_non_blocking(true)?; Ok(sock) } + #[instrument] fn new_udp_send_socket_ipv4() -> Result { let sock = Self::new(Domain::IPV4, Type::RAW, Some(Protocol::from(IPPROTO_RAW)))?; sock.set_non_blocking(true)?; @@ -292,12 +309,14 @@ impl TracerSocket for Socket { Ok(sock) } + #[instrument] fn new_udp_send_socket_ipv6() -> Result { let sock = Self::new(Domain::IPV6, Type::RAW, Some(Protocol::UDP))?; sock.set_non_blocking(true)?; Ok(sock) } + #[instrument] fn new_recv_socket_ipv4(src_addr: Ipv4Addr) -> Result { let mut sock = Self::new(Domain::IPV4, Type::RAW, Some(Protocol::ICMPV4))?; sock.bind(SocketAddr::new(IpAddr::V4(src_addr), 0))?; @@ -307,6 +326,7 @@ impl TracerSocket for Socket { Ok(sock) } + #[instrument] fn new_recv_socket_ipv6(src_addr: Ipv6Addr) -> Result { let mut sock = Self::new(Domain::IPV6, Type::RAW, Some(Protocol::ICMPV6))?; sock.bind(SocketAddr::new(IpAddr::V6(src_addr), 0))?; @@ -315,6 +335,7 @@ impl TracerSocket for Socket { Ok(sock) } + #[instrument] fn new_stream_socket_ipv4() -> Result { let sock = Self::new(Domain::IPV4, Type::STREAM, Some(Protocol::TCP))?; sock.set_non_blocking(true)?; @@ -322,6 +343,7 @@ impl TracerSocket for Socket { Ok(sock) } + #[instrument] fn new_stream_socket_ipv6() -> Result { let sock = Self::new(Domain::IPV6, Type::STREAM, Some(Protocol::TCP))?; sock.set_non_blocking(true)?; @@ -329,14 +351,17 @@ impl TracerSocket for Socket { Ok(sock) } + #[instrument] fn new_udp_dgram_socket_ipv4() -> Result { Self::new(Domain::IPV4, Type::DGRAM, Some(Protocol::UDP)) } + #[instrument] fn new_udp_dgram_socket_ipv6() -> Result { Self::new(Domain::IPV6, Type::DGRAM, Some(Protocol::UDP)) } + #[instrument(skip(self))] fn bind(&mut self, source_socketaddr: SocketAddr) -> Result<()> { self.inner .bind(&SockAddr::from(source_socketaddr)) @@ -351,14 +376,17 @@ impl TracerSocket for Socket { Ok(()) } + #[instrument(skip(self))] fn set_tos(&self, tos: u32) -> Result<()> { self.inner.set_tos(tos) } + #[instrument(skip(self))] fn set_ttl(&self, ttl: u32) -> Result<()> { self.inner.set_ttl(ttl) } + #[instrument(skip(self))] fn set_reuse_port(&self, is_reuse_port: bool) -> Result<()> { self.setsockopt_bool(SOL_SOCKET as _, SO_REUSE_UNICASTPORT as _, is_reuse_port) .or_else(|_| { @@ -366,14 +394,17 @@ impl TracerSocket for Socket { }) } + #[instrument(skip(self))] fn set_header_included(&self, is_header_included: bool) -> Result<()> { self.inner.set_header_included(is_header_included) } + #[instrument(skip(self))] fn set_unicast_hops_v6(&self, max_hops: u8) -> Result<()> { self.inner.set_unicast_hops_v6(max_hops.into()) } + #[instrument(skip(self))] fn connect(&self, dest_socketaddr: SocketAddr) -> Result<()> { self.set_fail_connect_on_icmp_error(true)?; syscall!( @@ -398,6 +429,7 @@ impl TracerSocket for Socket { Ok(()) } + #[instrument(skip(self))] fn is_readable(&self, timeout: Duration) -> Result { if !self.wait_for_event(timeout)? { return Ok(false); @@ -411,6 +443,7 @@ impl TracerSocket for Socket { Ok(true) } + #[instrument(skip(self))] fn is_writable(&self) -> Result { if !self.wait_for_event(Duration::ZERO)? { return Ok(false); @@ -440,14 +473,17 @@ impl TracerSocket for Socket { Ok(MAX_PACKET_SIZE) } + #[instrument(skip(self))] fn shutdown(&self) -> Result<()> { self.inner.shutdown(std::net::Shutdown::Both) } + #[instrument(skip(self), ret)] fn peer_addr(&self) -> Result> { Ok(self.inner.peer_addr()?.as_socket()) } + #[instrument(skip(self), ret)] fn take_error(&self) -> Result> { match self.getsockopt(SOL_SOCKET as _, SO_ERROR as _, 0) { Ok(0) => Ok(None), @@ -456,6 +492,7 @@ impl TracerSocket for Socket { } } + #[instrument(skip(self), ret)] #[allow(unsafe_code)] fn icmp_error_info(&self) -> Result { let icmp_error_info = self.getsockopt::( @@ -476,6 +513,7 @@ impl TracerSocket for Socket { } // Interestingly, Socket2 sockets don't seem to call closesocket on drop?? + #[instrument(skip(self))] fn close(&self) -> Result<()> { syscall!(closesocket(self.inner.as_raw_socket() as _), |res| res == SOCKET_ERROR) @@ -487,6 +525,7 @@ impl TracerSocket for Socket { /// is using a connectionless protocol, the address may not be available until I/O /// occurs on the socket." We use `SIO_ROUTING_INTERFACE_QUERY` instead. #[allow(clippy::cast_sign_loss)] +#[instrument] fn routing_interface_query(target: IpAddr) -> TraceResult { let src: *mut c_void = [0; 1024].as_mut_ptr().cast(); let mut bytes = 0; @@ -611,6 +650,7 @@ fn socketaddr_to_sockaddr(socketaddr: SocketAddr) -> (SOCKADDR_STORAGE, i32) { (unsafe { sockaddr.storage }, size_of::() as i32) } +#[instrument(skip(adapters), ret)] fn lookup_interface_addr(adapters: &Adapters, name: &str) -> TraceResult { adapters .iter() diff --git a/src/tracing/tracer.rs b/src/tracing/tracer.rs index 03500624..3fbc4735 100644 --- a/src/tracing/tracer.rs +++ b/src/tracing/tracer.rs @@ -10,6 +10,7 @@ use crate::tracing::{MultipathStrategy, PortDirection, TracerProtocol}; use crate::tracing::{Probe, TracerConfig}; use std::net::IpAddr; use std::time::{Duration, SystemTime}; +use tracing::instrument; /// The output from a round of tracing. #[derive(Debug, Clone)] @@ -50,7 +51,9 @@ pub struct Tracer { } impl)> Tracer { + #[instrument(skip_all)] pub fn new(config: &TracerConfig, publish: F) -> Self { + tracing::debug!(?config); Self { config: *config, publish, @@ -58,6 +61,7 @@ impl)> Tracer { } /// Run a continuous trace and publish results. + #[instrument(skip(self, network))] pub fn trace(self, mut network: N) -> TraceResult<()> { let mut state = TracerState::new(self.config); while !state.finished(self.config.max_rounds) { @@ -78,6 +82,7 @@ impl)> Tracer { /// - the next ttl is not greater than the ttl of the target host observed from the prior round /// otherwise: /// - the number of unknown-in-flight probes is lower than the maximum allowed + #[instrument(skip(self, network, st))] fn send_request(&self, network: &mut N, st: &mut TracerState) -> TraceResult<()> { let can_send_ttl = if let Some(target_ttl) = st.target_ttl() { st.ttl() <= target_ttl @@ -131,6 +136,7 @@ impl)> Tracer { /// When we process an `EchoReply` from the target host we extract the time-to-live from the corresponding /// original `EchoRequest`. Note that this may not be the greatest time-to-live that was sent in the round as /// the algorithm will send `EchoRequest` with larger time-to-live values before the `EchoReply` is received. + #[instrument(skip(self, network, st))] fn recv_response(&self, network: &mut N, st: &mut TracerState) -> TraceResult<()> { let next = network.recv_probe()?; match next { @@ -173,6 +179,7 @@ impl)> Tracer { /// 3 - either: /// A - the target has been found OR /// B - the target has not been found and the round has exceeded the maximum round duration + #[instrument(skip(self, st))] fn update_round(&self, st: &mut TracerState) { let now = SystemTime::now(); let round_duration = now.duration_since(st.round_start()).unwrap_or_default(); @@ -190,6 +197,7 @@ impl)> Tracer { /// /// If the round completed without receiving an `EchoReply` from the target host then we also publish the next /// `Probe` which is assumed to represent the TTL of the target host. + #[instrument(skip(self, state))] fn publish_trace(&self, state: &TracerState) { let max_received_ttl = if let Some(target_ttl) = state.target_ttl() { target_ttl @@ -214,11 +222,13 @@ impl)> Tracer { /// Check if the `TraceId` matches the expected value for this tracer. /// /// A special value of `0` is accepted for `udp` and `tcp` which do not have an identifier. + #[instrument(skip(self))] fn check_trace_id(&self, trace_id: TraceId) -> bool { self.config.trace_identifier == trace_id || trace_id == TraceId(0) } /// Extract the `TraceId`, `Sequence`, `SystemTime` and `IpAddr` from the `ProbeResponseData` in a protocol specific way. + #[instrument(skip(self))] fn extract(&self, resp: &ProbeResponseData) -> (TraceId, Sequence, SystemTime, IpAddr) { match resp.resp_seq { ProbeResponseSeq::Icmp(ProbeResponseSeqIcmp { @@ -271,6 +281,7 @@ mod state { }; use std::net::IpAddr; use std::time::SystemTime; + use tracing::instrument; /// The maximum number of `Probe` entries in the buffer. /// @@ -401,6 +412,7 @@ mod state { /// /// We post-increment `ttl` here and so in practice we only allow `ttl` values in the range `1..254` to allow /// us to use a `u8`. + #[instrument(skip(self))] pub fn next_probe(&mut self) -> Probe { let (src_port, dest_port, identifier) = self.probe_data(); let probe = Probe::new( @@ -428,6 +440,7 @@ mod state { /// For example, if the sequence is `4` and the `ttl` is `5` prior to calling this method then afterwards: /// - The `Probe` at sequence `3` will be reset to default values (i.e. `NotSent` status) /// - A new `Probe` will be created at sequence `4` with a `ttl` of `5` + #[instrument(skip(self))] pub fn reissue_probe(&mut self) -> Probe { self.buffer[usize::from(self.sequence - self.round_sequence) - 1] = Probe::default(); let (src_port, dest_port, identifier) = self.probe_data(); @@ -525,6 +538,7 @@ mod state { } /// Mark the `Probe` at `sequence` completed as `TimeExceeded` and update the round state. + #[instrument(skip(self))] pub fn complete_probe_time_exceeded( &mut self, sequence: Sequence, @@ -542,6 +556,7 @@ mod state { } /// Mark the `Probe` at `sequence` completed as `Unreachable` and update the round state. + #[instrument(skip(self))] pub fn complete_probe_unreachable( &mut self, sequence: Sequence, @@ -552,6 +567,7 @@ mod state { } /// Mark the `Probe` at `sequence` completed as `EchoReply` and update the round state. + #[instrument(skip(self))] pub fn complete_probe_echo_reply( &mut self, sequence: Sequence, @@ -562,6 +578,7 @@ mod state { } /// Mark the `Probe` at `sequence` completed as `NotApplicable` and update the round state. + #[instrument(skip(self))] pub fn complete_probe_other( &mut self, sequence: Sequence, @@ -589,6 +606,7 @@ mod state { /// The ICMP replies may arrive out-of-order and so we must be careful here to avoid overwriting the state with /// stale values. We may also receive multiple replies from the target host with differing time-to-live values /// and so must ensure we use the time-to-live with the lowest sequence number. + #[instrument(skip(self))] fn complete_probe( &mut self, sequence: Sequence, @@ -640,6 +658,7 @@ mod state { /// If, during the rond which just completed, we went above the max sequence number then we reset it here. /// We do this here to avoid having to deal with the sequence number wrapping during a round, which is more /// problematic. + #[instrument(skip(self))] pub fn advance_round(&mut self, first_ttl: TimeToLive) { if self.sequence >= MAX_SEQUENCE { self.sequence = self.config.initial_sequence; diff --git a/trippy-config-sample.toml b/trippy-config-sample.toml index 2dfe7988..50d7ad85 100644 --- a/trippy-config-sample.toml +++ b/trippy-config-sample.toml @@ -32,6 +32,26 @@ # silent - Do not generate any output for N cycles mode = "tui" +# How to format log data. +# +# Allowed values are: +# compact - Display log data in a compact format +# pretty - Display log data in a pretty format [default] +# json - Display log data in a json format +# chrome - Display log data in Chrome trace format +log-format = "pretty" + +# The debug log filter [default: trippy=debug] +log-filter = "trippy=debug" + +# How to log event spans. +# +# Allowed values are: +# off - Do not display event spans [defsult] +# active - Display enter and exit event spans +# full - Display all event spans +log-span-events = "off" + # # Tracing strategy configuration.