From a5c5e7d36fbeeac10b61f1db83534886d0e897eb Mon Sep 17 00:00:00 2001 From: Austin Gill Date: Mon, 7 Aug 2023 14:28:20 -0500 Subject: [PATCH] Add optional tracing feature for development logging --- Cargo.toml | 8 +- examples/forward.rs | 19 ++-- src/driver/socketcan.rs | 32 +++++- src/lib.rs | 1 + src/tracing.rs | 228 ++++++++++++++++++++++++++++++++++++++++ 5 files changed, 269 insertions(+), 19 deletions(-) create mode 100644 src/tracing.rs diff --git a/Cargo.toml b/Cargo.toml index 5d79d06..4185d23 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -9,18 +9,20 @@ keywords = ["agriculture", "can", "canbus", "isobus", "j1939", "agritech", "smar [dependencies] rand = "0.8.5" socketcan = { version = "2.0.0", optional = true } +tracing = { version = "0.1.37", optional = true } [features] default = [] +# Socketcan driver socketcan = ["dep:socketcan"] +# Optional logging instrumentation +tracing = ["dep:tracing"] [dev-dependencies] clap = { version = "4.3.19", features = ["derive"] } ctrlc = "3.4.0" -# TODO: Add optional tracing to the main library -tracing = "0.1.37" tracing-subscriber = "0.3.17" [[example]] name = "forward" -required-features = ["socketcan"] +required-features = ["socketcan", "tracing"] diff --git a/examples/forward.rs b/examples/forward.rs index a90c5fd..e843bca 100644 --- a/examples/forward.rs +++ b/examples/forward.rs @@ -2,7 +2,8 @@ use std::sync::mpsc::channel; -use ag_iso_stack::driver::{Driver, DriverReadError, Frame, SocketcanDriver}; +use ag_iso_stack::driver::{Driver, Frame, SocketcanDriver}; +use ag_iso_stack::tracing; use clap::Parser; /// Forward CAN traffic from one interface to another @@ -38,7 +39,7 @@ fn main() { let opts = Options::parse(); let subscriber = tracing_subscriber::fmt() - // ... add configuration + .with_max_level(opts.log_level) .finish(); tracing::subscriber::set_global_default(subscriber) .map_err(|_err| eprintln!("Unable to set global default subscriber")) @@ -66,17 +67,11 @@ fn main() { let mut frame = Frame::default(); - match input.read_nonblocking(&mut frame) { - Ok(_) => { - tracing::info!("Read frame: {frame:?}"); - tracing::info!("Attempting to write frame"); - match output.write_nonblocking(&frame) { - Ok(_) => tracing::info!("Wrote frame: {frame:?}"), - Err(e) => tracing::info!("Failed to write frame: {e:?}"), - } + #[allow(clippy::collapsible_if)] + if input.read_nonblocking(&mut frame).is_ok() { + if output.write_nonblocking(&frame).is_err() { + break; } - Err(DriverReadError::NoFrameReady) => {} - Err(e) => tracing::error!("Failed to read frame: {e:?}"), } } } diff --git a/src/driver/socketcan.rs b/src/driver/socketcan.rs index 09b0e35..4d41b3a 100644 --- a/src/driver/socketcan.rs +++ b/src/driver/socketcan.rs @@ -8,6 +8,7 @@ use crate::driver::{ CanId, Channel, Driver, DriverCloseError, DriverOpenError, DriverReadError, DriverWriteError, Frame as InternalFrame, Type, }; +use crate::tracing; impl From for DriverReadError { fn from(e: socketcan::Error) -> DriverReadError { @@ -39,6 +40,7 @@ impl From<&InternalFrame> for socketcan::frame::CanDataFrame { } } +#[derive(Debug, Clone, PartialEq, Eq)] enum SocketcanIface { Name(String), Index(u32), @@ -116,9 +118,17 @@ impl Driver for SocketcanDriver { self.sock.is_some() } fn open(&mut self) -> Result<(), DriverOpenError> { - match &self.iface { - SocketcanIface::Name(s) => self.sock = Some(CanSocket::open(s)?), - SocketcanIface::Index(i) => self.sock = Some(CanSocket::open_iface(*i)?), + tracing::info!("Opening interface {:?}", self.iface); + let result = match &self.iface { + SocketcanIface::Name(s) => CanSocket::open(s), + SocketcanIface::Index(i) => CanSocket::open_iface(*i), + }; + match result { + Ok(sock) => self.sock = Some(sock), + Err(e) => { + tracing::error!("Error '{e:?}' opening interface {:?}", self.iface); + return Err(e.into()); + } } self.opened_timestamp = Instant::now(); @@ -127,6 +137,7 @@ impl Driver for SocketcanDriver { Ok(()) } fn close(&mut self) -> Result<(), DriverCloseError> { + tracing::info!("Closing interface {:?}", self.iface); self.sock = None; Ok(()) } @@ -136,18 +147,31 @@ impl Driver for SocketcanDriver { /// The timestamp on the frame is the duration since [`open`](Self::open) was last called. fn read_nonblocking(&mut self, frame: &mut InternalFrame) -> Result<(), DriverReadError> { let Some(sock) = self.sock.as_mut() else { + tracing::warn!("Failed to read from closed interface {:?}", self.iface); return Err(DriverReadError::DriverClosed); }; let socketcan_frame = sock.read_frame()?; *frame = self.to_frame(socketcan_frame); + tracing::trace!("Read frame {frame:?} from interface {:?}", self.iface); Ok(()) } fn write_nonblocking(&mut self, frame: &InternalFrame) -> Result<(), DriverWriteError> { let Some(sock) = self.sock.as_mut() else { + tracing::warn!("Tried to write to closed interface {:?}", self.iface); return Err(DriverWriteError::DriverClosed); }; let socketcan_frame: socketcan::frame::CanDataFrame = frame.into(); - sock.write_frame(&socketcan_frame)?; + match sock.write_frame(&socketcan_frame) { + Ok(_) => tracing::trace!("Wrote frame {frame:?} to interface {:?}", self.iface), + Err(_e) => { + if _e.kind() != std::io::ErrorKind::WouldBlock { + tracing::error!( + "Error '{_e:?}' writing frame {frame:?} to interface {:?}", + self.iface + ); + } + } + } Ok(()) } } diff --git a/src/lib.rs b/src/lib.rs index 2b835fb..dcbcb6c 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -5,3 +5,4 @@ pub mod driver; pub mod network_management; +pub mod tracing; diff --git a/src/tracing.rs b/src/tracing.rs new file mode 100644 index 0000000..4ed0748 --- /dev/null +++ b/src/tracing.rs @@ -0,0 +1,228 @@ +//! # Tracing +//! +//! AgIsoStack-rs provides tracing under the non-default `tracing` Cargo feature. Tracing is +//! intended for use by Crate maintainers for introspection. We use the [tracing] crate, but rather +//! than invoke `tracing`s macros directly, we provide our own shim layer, so that we don't need to +//! sprinkle `#[cfg(feature = "tracing")]` a bazillion places throughout the crate. + +#[cfg(feature = "tracing")] +pub use tracing::*; + +/// A conditional compilation shim around [tracing::debug!] +// NOTE: I tried to make this mess less gross by implementing the macro like +// +// macro_rules! debug { +// ( $($all_tokens:tt)* ) => { +// #[cfg(feature = "tracing")] +// ::tracing::debug!($($all_tokens)*) +// }; +// } +// +// with various combinations of semi-colons and curly braces. No matter what, I couldn't find a way +// to get this macro to correctly expand when using the log statements as expressions as in +// +// match foo() { +// Ok(x) => tracing::debug!("Ok: {x:?}"), +// Err(e) => tracing::debug("Err: {e:?}"), +// } +// +// So here, I hoist the #[cfg] attribute up a level to the actual macro definition. It's gross, way +// more typing than I wanted, but it works. +#[macro_export] +#[cfg(feature = "tracing")] +macro_rules! __debug { + ( $($all_tokens:tt)* ) => { ::tracing::debug!($($all_tokens)*) }; +} +#[macro_export] +#[cfg(not(feature = "tracing"))] +macro_rules! __debug { + ( $($all_tokens:tt)* ) => {{}}; +} +// HACK: This is a gross and dirty hack that shouldn't need to exist. When you use #[macro_export], +// that exports the macro under the top-level crate module for technical reasons (I think because +// when macros are expanded the module tree doesn't exist yet?). This re-export trick came from the +// rust-analyzer source code (thanks matklad!) and makes these macros available under the +// crate::tracing module. +pub use __debug as debug; + +/// A conditional compilation shim around [tracing::debug_span!] +#[macro_export] +#[cfg(feature = "tracing")] +macro_rules! __debug_span { + ( $($all_tokens:tt)* ) => { ::tracing::debug_span!($($all_tokens)*) }; +} +#[macro_export] +#[cfg(not(feature = "tracing"))] +macro_rules! __debug_span { + ( $($all_tokens:tt)* ) => {{}}; +} +pub use __debug_span as debug_span; + +/// A conditional compilation shim around [tracing::enabled!] +#[macro_export] +#[cfg(feature = "tracing")] +macro_rules! __enabled { + ( $($all_tokens:tt)* ) => { ::tracing::enabled!($($all_tokens)*) }; +} +#[macro_export] +#[cfg(not(feature = "tracing"))] +macro_rules! __enabled { + ( $($all_tokens:tt)* ) => {{}}; +} +pub use __enabled as enabled; + +/// A conditional compilation shim around [tracing::error!] +#[macro_export] +#[cfg(feature = "tracing")] +macro_rules! __error { + ( $($all_tokens:tt)* ) => { ::tracing::error!($($all_tokens)*) }; +} +#[macro_export] +#[cfg(not(feature = "tracing"))] +macro_rules! __error { + ( $($all_tokens:tt)* ) => {{}}; +} +pub use __error as error; + +/// A conditional compilation shim around [tracing::error_span!] +#[macro_export] +#[cfg(feature = "tracing")] +macro_rules! __error_span { + ( $($all_tokens:tt)* ) => { ::tracing::error_span!($($all_tokens)*) }; +} +#[macro_export] +#[cfg(not(feature = "tracing"))] +macro_rules! __error_span { + ( $($all_tokens:tt)* ) => {{}}; +} +pub use __error_span as error_span; + +/// A conditional compilation shim around [tracing::event!] +#[macro_export] +#[cfg(feature = "tracing")] +macro_rules! __event { + ( $($all_tokens:tt)* ) => { ::tracing::event!($($all_tokens)*) }; +} +#[macro_export] +#[cfg(not(feature = "tracing"))] +macro_rules! __event { + ( $($all_tokens:tt)* ) => {{}}; +} +pub use __event as event; + +/// A conditional compilation shim around [tracing::event_enabled!] +#[macro_export] +#[cfg(feature = "tracing")] +macro_rules! __event_enabled { + ( $($all_tokens:tt)* ) => { ::tracing::event_enabled!($($all_tokens)*) }; +} +#[macro_export] +#[cfg(not(feature = "tracing"))] +macro_rules! __event_enabled { + ( $($all_tokens:tt)* ) => {{}}; +} +pub use __event_enabled as event_enabled; + +/// A conditional compilation shim around [tracing::info!] +#[macro_export] +#[cfg(feature = "tracing")] +macro_rules! __info { + ( $($all_tokens:tt)* ) => { ::tracing::info!($($all_tokens)*) }; +} +#[macro_export] +#[cfg(not(feature = "tracing"))] +macro_rules! __info { + ( $($all_tokens:tt)* ) => {{}}; +} +pub use __info as info; + +/// A conditional compilation shim around [tracing::info_span!] +#[macro_export] +#[cfg(feature = "tracing")] +macro_rules! __info_span { + ( $($all_tokens:tt)* ) => { ::tracing::info_span!($($all_tokens)*) }; +} +#[macro_export] +#[cfg(not(feature = "tracing"))] +macro_rules! __info_span { + ( $($all_tokens:tt)* ) => {{}}; +} +pub use __info_span as info_span; + +/// A conditional compilation shim around [tracing::span!] +#[macro_export] +#[cfg(feature = "tracing")] +macro_rules! __span { + ( $($all_tokens:tt)* ) => { ::tracing::span!($($all_tokens)*) }; +} +#[macro_export] +#[cfg(not(feature = "tracing"))] +macro_rules! __span { + ( $($all_tokens:tt)* ) => {{}}; +} +pub use __span as span; + +/// A conditional compilation shim around [tracing::span_enabled!] +#[macro_export] +#[cfg(feature = "tracing")] +macro_rules! __span_enabled { + ( $($all_tokens:tt)* ) => { ::tracing::span_enabled!($($all_tokens)*) }; +} +#[macro_export] +#[cfg(not(feature = "tracing"))] +macro_rules! __span_enabled { + ( $($all_tokens:tt)* ) => {{}}; +} +pub use __span_enabled as span_enabled; + +/// A conditional compilation shim around [tracing::trace!] +#[macro_export] +#[cfg(feature = "tracing")] +macro_rules! __trace { + ( $($all_tokens:tt)* ) => { ::tracing::trace!($($all_tokens)*) }; +} +#[macro_export] +#[cfg(not(feature = "tracing"))] +macro_rules! __trace { + ( $($all_tokens:tt)* ) => {{}}; +} +pub use __trace as trace; + +/// A conditional compilation shim around [tracing::trace_span!] +#[macro_export] +#[cfg(feature = "tracing")] +macro_rules! __trace_span { + ( $($all_tokens:tt)* ) => { ::tracing::trace_span!($($all_tokens)*) }; +} +#[macro_export] +#[cfg(not(feature = "tracing"))] +macro_rules! __trace_span { + ( $($all_tokens:tt)* ) => {{}}; +} +pub use __trace_span as trace_span; + +/// A conditional compilation shim around [tracing::warn!] +#[macro_export] +#[cfg(feature = "tracing")] +macro_rules! __warn { + ( $($all_tokens:tt)* ) => { ::tracing::warn!($($all_tokens)*) }; +} +#[macro_export] +#[cfg(not(feature = "tracing"))] +macro_rules! __warn { + ( $($all_tokens:tt)* ) => {{}}; +} +pub use __warn as warn; + +/// A conditional compilation shim around [tracing::warn_span!] +#[macro_export] +#[cfg(feature = "tracing")] +macro_rules! __warn_span { +( $($all_tokens:tt)* ) => { ::tracing::warn_span!($($all_tokens)*) }; +} +#[macro_export] +#[cfg(not(feature = "tracing"))] +macro_rules! __warn_span { + ( $($all_tokens:tt)* ) => {{}}; +} +pub use __warn_span as warn_span;