diff --git a/Cargo.lock b/Cargo.lock index 0161196c1..38c88f41b 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 f95c1319c..120fbec06 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 ceff3f5a2..412071a26 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 88a7b131d..d984930f8 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 5f9f86955..372e803c0 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 8f6c9d46e..74d9527a1 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 27a151e9e..bb3f201a0 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 e15835cba..9336a6d3c 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 6779d00b2..a4913005f 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"))] @@ -102,6 +104,7 @@ pub fn lookup_interface_addr_ipv6(name: &str) -> TraceResult { } #[allow(clippy::unnecessary_wraps)] +#[instrument] pub fn startup() -> TraceResult<()> { Ok(()) } @@ -165,82 +168,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 +277,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 +290,46 @@ impl TracerSocket for Socket { )?; Ok(writable == 1) } + #[instrument(skip(self, buf))] 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))] 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))] 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))] fn take_error(&self) -> io::Result> { self.inner.take_error() } #[allow(clippy::unused_self, clippy::unnecessary_wraps)] + #[instrument(skip(self))] 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/tracer.rs b/src/tracing/tracer.rs index 035006246..3fbc4735b 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 2dfe7988a..50d7ad85d 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.