Add optional tracing feature for development logging

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"]

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:?}"),
         }
     }
 }

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<socketcan::Error> 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(())
     }
 }

src/lib.rs

@@ -5,3 +5,4 @@
 
 pub mod driver;
 pub mod network_management;
+pub mod tracing;

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;