Replace log with tracing (#119)

Cargo.toml

@@ -23,7 +23,7 @@ std = []
 
 [dependencies]
 cfg-if = "1"
-log = "0.4.11"
+tracing = { version = "0.1.37", default-features = false }
 
 [target.'cfg(any(unix, target_os = "fuchsia", target_os = "vxworks"))'.dependencies]
 libc = "0.2.77"

src/epoll.rs

@@ -65,11 +65,11 @@ impl Poller {
             PollMode::Oneshot,
         )?;
 
-        log::trace!(
-            "new: epoll_fd={}, event_fd={}, timer_fd={:?}",
-            poller.epoll_fd.as_raw_fd(),
-            poller.event_fd.as_raw_fd(),
-            poller.timer_fd
+        tracing::trace!(
+            epoll_fd = ?poller.epoll_fd.as_raw_fd(),
+            event_fd = ?poller.event_fd.as_raw_fd(),
+            timer_fd = ?poller.timer_fd,
+            "new",
         );
         Ok(poller)
     }
@@ -86,12 +86,13 @@ impl Poller {
 
     /// Adds a new file descriptor.
     pub fn add(&self, fd: RawFd, ev: Event, mode: PollMode) -> io::Result<()> {
-        log::trace!(
-            "add: epoll_fd={}, fd={}, ev={:?}",
-            self.epoll_fd.as_raw_fd(),
-            fd,
-            ev
+        let span = tracing::trace_span!(
+            "add",
+            epoll_fd = ?self.epoll_fd.as_raw_fd(),
+            ?fd,
+            ?ev,
         );
+        let _enter = span.enter();
 
         epoll::epoll_add(
             &self.epoll_fd,
@@ -105,12 +106,13 @@ impl Poller {
 
     /// Modifies an existing file descriptor.
     pub fn modify(&self, fd: RawFd, ev: Event, mode: PollMode) -> io::Result<()> {
-        log::trace!(
-            "modify: epoll_fd={}, fd={}, ev={:?}",
-            self.epoll_fd.as_raw_fd(),
-            fd,
-            ev
+        let span = tracing::trace_span!(
+            "modify",
+            epoll_fd = ?self.epoll_fd.as_raw_fd(),
+            ?fd,
+            ?ev,
         );
+        let _enter = span.enter();
 
         epoll::epoll_mod(
             &self.epoll_fd,
@@ -124,7 +126,12 @@ impl Poller {
 
     /// Deletes a file descriptor.
     pub fn delete(&self, fd: RawFd) -> io::Result<()> {
-        log::trace!("remove: epoll_fd={}, fd={}", self.epoll_fd.as_raw_fd(), fd);
+        let span = tracing::trace_span!(
+            "delete",
+            epoll_fd = ?self.epoll_fd.as_raw_fd(),
+            ?fd,
+        );
+        let _enter = span.enter();
 
         epoll::epoll_del(&self.epoll_fd, unsafe {
             rustix::fd::BorrowedFd::borrow_raw(fd)
@@ -136,11 +143,12 @@ impl Poller {
     /// Waits for I/O events with an optional timeout.
     #[allow(clippy::needless_update)]
     pub fn wait(&self, events: &mut Events, timeout: Option<Duration>) -> io::Result<()> {
-        log::trace!(
-            "wait: epoll_fd={}, timeout={:?}",
-            self.epoll_fd.as_raw_fd(),
-            timeout
+        let span = tracing::trace_span!(
+            "wait",
+            epoll_fd = ?self.epoll_fd.as_raw_fd(),
+            ?timeout,
         );
+        let _enter = span.enter();
 
         if let Some(ref timer_fd) = self.timer_fd {
             // Configure the timeout using timerfd.
@@ -188,10 +196,10 @@ impl Poller {
 
         // Wait for I/O events.
         epoll::epoll_wait(&self.epoll_fd, &mut events.list, timeout_ms)?;
-        log::trace!(
-            "new events: epoll_fd={}, res={}",
-            self.epoll_fd.as_raw_fd(),
-            events.list.len()
+        tracing::trace!(
+            epoll_fd = ?self.epoll_fd.as_raw_fd(),
+            res = ?events.list.len(),
+            "new events",
         );
 
         // Clear the notification (if received) and re-register interest in it.
@@ -211,11 +219,12 @@ impl Poller {
 
     /// Sends a notification to wake up the current or next `wait()` call.
     pub fn notify(&self) -> io::Result<()> {
-        log::trace!(
-            "notify: epoll_fd={}, event_fd={}",
-            self.epoll_fd.as_raw_fd(),
-            self.event_fd.as_raw_fd()
+        let span = tracing::trace_span!(
+            "notify",
+            epoll_fd = ?self.epoll_fd.as_raw_fd(),
+            event_fd = ?self.event_fd.as_raw_fd(),
         );
+        let _enter = span.enter();
 
         let buf: [u8; 8] = 1u64.to_ne_bytes();
         let _ = write(&self.event_fd, &buf);
@@ -237,12 +246,13 @@ impl AsFd for Poller {
 
 impl Drop for Poller {
     fn drop(&mut self) {
-        log::trace!(
-            "drop: epoll_fd={}, event_fd={}, timer_fd={:?}",
-            self.epoll_fd.as_raw_fd(),
-            self.event_fd.as_raw_fd(),
-            self.timer_fd
+        let span = tracing::trace_span!(
+            "drop",
+            epoll_fd = ?self.epoll_fd.as_raw_fd(),
+            event_fd = ?self.event_fd.as_raw_fd(),
+            timer_fd = ?self.timer_fd
         );
+        let _enter = span.enter();
 
         if let Some(timer_fd) = self.timer_fd.take() {
             let _ = self.delete(timer_fd.as_raw_fd());

src/iocp/afd.rs

@@ -6,7 +6,7 @@ use std::cell::UnsafeCell;
 use std::fmt;
 use std::io;
 use std::marker::{PhantomData, PhantomPinned};
-use std::mem::{size_of, transmute, MaybeUninit};
+use std::mem::{self, size_of, transmute, MaybeUninit};
 use std::os::windows::prelude::{AsRawHandle, RawHandle, RawSocket};
 use std::pin::Pin;
 use std::ptr;
@@ -111,7 +111,7 @@ macro_rules! define_ntdll_import {
                         let addr = match addr {
                             Some(addr) => addr,
                             None => {
-                                log::error!("Failed to load ntdll function {}", NAME);
+                                tracing::error!("Failed to load ntdll function {}", NAME);
                                 return Err(io::Error::last_os_error());
                             },
                         };
@@ -212,7 +212,7 @@ impl NtdllImports {
                 let ntdll = GetModuleHandleW(NTDLL_NAME.as_ptr() as *const _);
 
                 if ntdll == 0 {
-                    log::error!("Failed to load ntdll.dll");
+                    tracing::error!("Failed to load ntdll.dll");
                     return Err(io::Error::last_os_error());
                 }
 
@@ -302,8 +302,8 @@ where
 
         // Set up device attributes.
         let mut device_name = UNICODE_STRING {
-            Length: (AFD_NAME.len() * size_of::<u16>()) as u16,
-            MaximumLength: (AFD_NAME.len() * size_of::<u16>()) as u16,
+            Length: mem::size_of_val(AFD_NAME) as u16,
+            MaximumLength: mem::size_of_val(AFD_NAME) as u16,
             Buffer: AFD_NAME.as_ptr() as *mut _,
         };
         let mut device_attributes = OBJECT_ATTRIBUTES {

src/iocp/mod.rs

@@ -105,7 +105,7 @@ impl Poller {
 
         let port = IoCompletionPort::new(0)?;
 
-        log::trace!("new: handle={:?}", &port);
+        tracing::trace!(handle = ?port, "new");
 
         Ok(Poller {
             port,
@@ -135,12 +135,13 @@ impl Poller {
 
     /// Add a new source to the poller.
     pub(super) fn add(&self, socket: RawSocket, interest: Event, mode: PollMode) -> io::Result<()> {
-        log::trace!(
-            "add: handle={:?}, sock={}, ev={:?}",
-            self.port,
-            socket,
-            interest
+        let span = tracing::trace_span!(
+            "add",
+            handle = ?self.port,
+            sock = ?socket,
+            ev = ?interest,
         );
+        let _enter = span.enter();
 
         // We don't support edge-triggered events.
         if matches!(mode, PollMode::Edge | PollMode::EdgeOneshot) {
@@ -195,12 +196,13 @@ impl Poller {
         interest: Event,
         mode: PollMode,
     ) -> io::Result<()> {
-        log::trace!(
-            "modify: handle={:?}, sock={}, ev={:?}",
-            self.port,
-            socket,
-            interest
+        let span = tracing::trace_span!(
+            "modify",
+            handle = ?self.port,
+            sock = ?socket,
+            ev = ?interest,
         );
+        let _enter = span.enter();
 
         // We don't support edge-triggered events.
         if matches!(mode, PollMode::Edge | PollMode::EdgeOneshot) {
@@ -230,7 +232,12 @@ impl Poller {
 
     /// Delete a source from the poller.
     pub(super) fn delete(&self, socket: RawSocket) -> io::Result<()> {
-        log::trace!("remove: handle={:?}, sock={}", self.port, socket);
+        let span = tracing::trace_span!(
+            "remove",
+            handle = ?self.port,
+            sock = ?socket,
+        );
+        let _enter = span.enter();
 
         // Get a reference to the source.
         let source = {
@@ -252,7 +259,12 @@ impl Poller {
 
     /// Wait for events.
     pub(super) fn wait(&self, events: &mut Events, timeout: Option<Duration>) -> io::Result<()> {
-        log::trace!("wait: handle={:?}, timeout={:?}", self.port, timeout);
+        let span = tracing::trace_span!(
+            "wait",
+            handle = ?self.port,
+            ?timeout,
+        );
+        let _enter = span.enter();
 
         let deadline = timeout.and_then(|timeout| Instant::now().checked_add(timeout));
         let mut packets = lock!(self.packets.lock());
@@ -279,7 +291,10 @@ impl Poller {
 
             // Wait for I/O events.
             let len = self.port.wait(&mut packets, timeout)?;
-            log::trace!("new events: handle={:?}, len={}", self.port, len);
+            tracing::trace!(
+                handle = ?self.port,
+                res = ?len,
+                "new events");
 
             // We are no longer polling.
             drop(guard);
@@ -308,7 +323,7 @@ impl Poller {
                 break;
             }
 
-            log::trace!("wait: no events found, re-entering polling loop");
+            tracing::trace!("wait: no events found, re-entering polling loop");
         }
 
         Ok(())

src/kqueue.rs

@@ -37,7 +37,10 @@ impl Poller {
         // Register the notification pipe.
         poller.notify.register(&poller)?;
 
-        log::trace!("new: kqueue_fd={:?}", poller.kqueue_fd);
+        tracing::trace!(
+            kqueue_fd = ?poller.kqueue_fd.as_raw_fd(),
+            "new"
+        );
         Ok(poller)
     }
 
@@ -59,14 +62,18 @@ impl Poller {
 
     /// Modifies an existing file descriptor.
     pub fn modify(&self, fd: RawFd, ev: Event, mode: PollMode) -> io::Result<()> {
-        if !self.notify.has_fd(fd) {
-            log::trace!(
-                "add: kqueue_fd={:?}, fd={}, ev={:?}",
-                self.kqueue_fd,
-                fd,
-                ev
+        let span = if !self.notify.has_fd(fd) {
+            let span = tracing::trace_span!(
+                "add",
+                kqueue_fd = ?self.kqueue_fd.as_raw_fd(),
+                ?fd,
+                ?ev,
             );
-        }
+            Some(span)
+        } else {
+            None
+        };
+        let _enter = span.as_ref().map(|s| s.enter());
 
         let mode_flags = mode_to_flags(mode);
 
@@ -141,18 +148,23 @@ impl Poller {
 
     /// Waits for I/O events with an optional timeout.
     pub fn wait(&self, events: &mut Events, timeout: Option<Duration>) -> io::Result<()> {
-        log::trace!(
-            "wait: kqueue_fd={:?}, timeout={:?}",
-            self.kqueue_fd,
-            timeout
+        let span = tracing::trace_span!(
+            "wait",
+            kqueue_fd = ?self.kqueue_fd.as_raw_fd(),
+            ?timeout,
         );
+        let _enter = span.enter();
 
         // Wait for I/O events.
         let changelist = [];
         let eventlist = &mut events.list;
         let res = unsafe { kqueue::kevent(&self.kqueue_fd, &changelist, eventlist, timeout)? };
 
-        log::trace!("new events: kqueue_fd={:?}, res={}", self.kqueue_fd, res);
+        tracing::trace!(
+            kqueue_fd = ?self.kqueue_fd.as_raw_fd(),
+            ?res,
+            "new events",
+        );
 
         // Clear the notification (if received) and re-register interest in it.
         self.notify.reregister(self)?;
@@ -162,7 +174,12 @@ impl Poller {
 
     /// Sends a notification to wake up the current or next `wait()` call.
     pub fn notify(&self) -> io::Result<()> {
-        log::trace!("notify: kqueue_fd={:?}", self.kqueue_fd);
+        let span = tracing::trace_span!(
+            "notify",
+            kqueue_fd = ?self.kqueue_fd.as_raw_fd(),
+        );
+        let _enter = span.enter();
+
         self.notify.notify(self).ok();
         Ok(())
     }
@@ -182,7 +199,12 @@ impl AsFd for Poller {
 
 impl Drop for Poller {
     fn drop(&mut self) {
-        log::trace!("drop: kqueue_fd={:?}", self.kqueue_fd);
+        let span = tracing::trace_span!(
+            "drop",
+            kqueue_fd = ?self.kqueue_fd.as_raw_fd(),
+        );
+        let _enter = span.enter();
+
         let _ = self.notify.deregister(self);
     }
 }