From 532a36774515549893f31e5c9cec07b208f69e74 Mon Sep 17 00:00:00 2001 From: Austin Gill Date: Mon, 7 Aug 2023 14:28:20 -0500 Subject: [PATCH] WIP: Add optional tracing --- Cargo.toml | 10 +- examples/forward.rs | 17 ++- src/driver/socketcan.rs | 71 +++++++++++-- src/lib.rs | 1 + src/tracing.rs | 228 ++++++++++++++++++++++++++++++++++++++++ 5 files changed, 304 insertions(+), 23 deletions(-) create mode 100644 src/tracing.rs diff --git a/Cargo.toml b/Cargo.toml index 4d043d3..3486a0d 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -8,14 +8,20 @@ keywords = ["agriculture", "can", "canbus", "isobus", "j1939", "agritech", "smar [dependencies] socketcan = { version = "2.0.0", optional = true } +tracing = { version = "0.1.37", optional = true } [features] default = ["socketcan"] +# 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", "tracing"] diff --git a/examples/forward.rs b/examples/forward.rs index 4378405..5b26b9e 100644 --- a/examples/forward.rs +++ b/examples/forward.rs @@ -1,6 +1,7 @@ use std::sync::mpsc::channel; use ag_iso_stack::driver::{Driver, DriverReadError, DriverWriteError, Frame, SocketcanDriver}; +use ag_iso_stack::tracing; use clap::Parser; /// Forward CAN traffic from one interface to another @@ -56,7 +57,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")) @@ -84,17 +85,11 @@ fn main() { let mut frame = Frame::default(); - match read(&mut input, &mut frame, opts.blocking) { - Ok(_) => { - tracing::info!("Read frame: {frame:?}"); - tracing::info!("Attempting to write frame"); - match write(&mut output, &frame, opts.blocking) { - Ok(_) => tracing::info!("Wrote frame: {frame:?}"), - Err(e) => tracing::info!("Failed to write frame: {e:?}"), - } + #[allow(clippy::collapsible_if)] + if read(&mut input, &mut frame, opts.blocking).is_ok() { + if write(&mut output, &frame, opts.blocking).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 c611fc3..3c1b5b8 100644 --- a/src/driver/socketcan.rs +++ b/src/driver/socketcan.rs @@ -3,6 +3,7 @@ use socketcan::{CanSocket, Socket}; use crate::driver::{ Driver, DriverCloseError, DriverOpenError, DriverReadError, DriverWriteError, Frame, }; +use crate::tracing; impl From for DriverReadError { fn from(e: socketcan::Error) -> DriverReadError { @@ -22,6 +23,7 @@ impl From for DriverWriteError { } } +#[derive(Debug)] enum SocketcanIface { Name(String), Index(u32), @@ -53,9 +55,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()); + } } // NOTE: To get any kind of non-blocking behavior, EVEN if using NonBlockingCan::receive() // you MUST set this flag. But setting this flag causes even BlockingCan::receive() to @@ -65,12 +75,14 @@ impl Driver for SocketcanDriver { Ok(()) } fn close(&mut self) -> Result<(), DriverCloseError> { + tracing::info!("Closing interface {:?}", self.iface); self.sock = None; Ok(()) } fn read_blocking(&mut self, _frame: &mut Frame) -> Result<(), DriverReadError> { let Some(sock) = self.sock.as_mut() else { + tracing::warn!("Failed to read from closed interface {:?}", self.iface); return Err(DriverReadError::DriverClosed); }; @@ -79,41 +91,80 @@ impl Driver for SocketcanDriver { // as fast as possible. match sock.read_frame_timeout(std::time::Duration::from_millis(100)) { Ok(_frame) => { + tracing::trace!("Read frame {_frame:?} from interface {:?}", self.iface); // TODO: convert socketcan CanFrame to Frame return Ok(()); } - Err(e) => match e.kind() { - std::io::ErrorKind::TimedOut => {} - _ => return Err(e.into()), - }, + Err(e) => { + if e.kind() != std::io::ErrorKind::TimedOut { + tracing::error!( + "Error '{e:?}' receiving frame from interface {:?}", + self.iface + ); + } else { + return Err(e.into()); + } + } } } } fn read_nonblocking(&mut self, _frame: &mut Frame) -> 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 _frame = sock.read_frame()?; + let _frame = match sock.read_frame() { + Ok(frame) => frame, + Err(e) => { + if e.kind() != std::io::ErrorKind::WouldBlock { + tracing::error!( + "Error '{e:?}' receiving frame from interface {:?}", + self.iface + ); + } + return Err(e.into()); + } + }; + tracing::trace!("Read frame {_frame:?} from interface {:?}", self.iface); + // TODO: Convert socketcan CanFrame to Frame. Ok(()) } fn write_blocking(&mut self, _frame: &Frame) -> Result<(), DriverWriteError> { let Some(sock) = self.sock.as_mut() else { + tracing::warn!("Tried to write to closed interface {:?}", self.iface); return Err(DriverWriteError::DriverClosed); }; // TODO: Convert Frame to socketcan CanFrame let socketcan_frame = socketcan::CanFrame::default(); - sock.write_frame_insist(&socketcan_frame)?; + match sock.write_frame_insist(&socketcan_frame) { + Ok(_) => tracing::trace!("Wrote frame {_frame:?} to interface {:?}", self.iface), + Err(_e) => tracing::error!( + "Error '{_e:?}' writing frame {_frame:?} to interface {:?}", + self.iface + ), + } Ok(()) } fn write_nonblocking(&mut self, _frame: &Frame) -> Result<(), DriverWriteError> { let Some(sock) = self.sock.as_mut() else { + tracing::warn!("Tried to write to closed interface {:?}", self.iface); return Err(DriverWriteError::DriverClosed); }; // TODO: Convert Frame to socketcan CanFrame let socketcan_frame = socketcan::CanFrame::default(); - 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 d6dc9b3..13131fd 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -3,3 +3,4 @@ #![allow(clippy::bool_assert_comparison)] pub mod driver; +pub mod tracing; diff --git a/src/tracing.rs b/src/tracing.rs new file mode 100644 index 0000000..aa4910a --- /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;