int: Use tracing instead of log

Cargo.toml

@@ -23,7 +23,7 @@ std = []
 
 [dependencies]
 cfg-if = "1"
-log = "0.4.11"
+tracing = { version = "0.1.37", default-features = false }
 
 [build-dependencies]
 autocfg = "1"

src/epoll.rs

@@ -79,7 +79,7 @@ impl Poller {
             },
         )?;
 
-        log::trace!(
+        tracing::trace!(
             "new: epoll_fd={}, event_fd={}, timer_fd={:?}",
             epoll_fd,
             event_fd,
@@ -90,25 +90,25 @@ impl Poller {
 
     /// Adds a new file descriptor.
     pub fn add(&self, fd: RawFd, ev: Event) -> io::Result<()> {
-        log::trace!("add: epoll_fd={}, fd={}, ev={:?}", self.epoll_fd, fd, ev);
+        tracing::trace!("add: epoll_fd={}, fd={}, ev={:?}", self.epoll_fd, fd, ev);
         self.ctl(libc::EPOLL_CTL_ADD, fd, Some(ev))
     }
 
     /// Modifies an existing file descriptor.
     pub fn modify(&self, fd: RawFd, ev: Event) -> io::Result<()> {
-        log::trace!("modify: epoll_fd={}, fd={}, ev={:?}", self.epoll_fd, fd, ev);
+        tracing::trace!("modify: epoll_fd={}, fd={}, ev={:?}", self.epoll_fd, fd, ev);
         self.ctl(libc::EPOLL_CTL_MOD, fd, Some(ev))
     }
 
     /// Deletes a file descriptor.
     pub fn delete(&self, fd: RawFd) -> io::Result<()> {
-        log::trace!("remove: epoll_fd={}, fd={}", self.epoll_fd, fd);
+        tracing::trace!("remove: epoll_fd={}, fd={}", self.epoll_fd, fd);
         self.ctl(libc::EPOLL_CTL_DEL, fd, None)
     }
 
     /// Waits for I/O events with an optional timeout.
     pub fn wait(&self, events: &mut Events, timeout: Option<Duration>) -> io::Result<()> {
-        log::trace!("wait: epoll_fd={}, timeout={:?}", self.epoll_fd, timeout);
+        tracing::trace!("wait: epoll_fd={}, timeout={:?}", self.epoll_fd, timeout);
 
         if let Some(timer_fd) = self.timer_fd {
             // Configure the timeout using timerfd.
@@ -165,7 +165,7 @@ impl Poller {
             timeout_ms as libc::c_int,
         ))?;
         events.len = res as usize;
-        log::trace!("new events: epoll_fd={}, res={}", self.epoll_fd, res);
+        tracing::trace!("new events: epoll_fd={}, res={}", self.epoll_fd, res);
 
         // Clear the notification (if received) and re-register interest in it.
         let mut buf = [0u8; 8];
@@ -187,7 +187,7 @@ impl Poller {
 
     /// Sends a notification to wake up the current or next `wait()` call.
     pub fn notify(&self) -> io::Result<()> {
-        log::trace!(
+        tracing::trace!(
             "notify: epoll_fd={}, event_fd={}",
             self.epoll_fd,
             self.event_fd
@@ -245,7 +245,7 @@ impl AsFd for Poller {
 
 impl Drop for Poller {
     fn drop(&mut self) {
-        log::trace!(
+        tracing::trace!(
             "drop: epoll_fd={}, event_fd={}, timer_fd={:?}",
             self.epoll_fd,
             self.event_fd,

src/kqueue.rs

@@ -49,7 +49,7 @@ impl Poller {
             },
         )?;
 
-        log::trace!(
+        tracing::trace!(
             "new: kqueue_fd={}, read_stream={:?}",
             kqueue_fd,
             poller.read_stream
@@ -66,7 +66,7 @@ impl Poller {
     /// Modifies an existing file descriptor.
     pub fn modify(&self, fd: RawFd, ev: Event) -> io::Result<()> {
         if fd != self.read_stream.as_raw_fd() {
-            log::trace!("add: kqueue_fd={}, fd={}, ev={:?}", self.kqueue_fd, fd, ev);
+            tracing::trace!("add: kqueue_fd={}, fd={}, ev={:?}", self.kqueue_fd, fd, ev);
         }
 
         let read_flags = if ev.readable {
@@ -132,7 +132,7 @@ 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);
+        tracing::trace!("wait: kqueue_fd={}, timeout={:?}", self.kqueue_fd, timeout);
 
         // Convert the `Duration` to `libc::timespec`.
         let timeout = timeout.map(|t| libc::timespec {
@@ -155,7 +155,7 @@ impl Poller {
             }
         ))?;
         events.len = res as usize;
-        log::trace!("new events: kqueue_fd={}, res={}", self.kqueue_fd, res);
+        tracing::trace!("new events: kqueue_fd={}, res={}", self.kqueue_fd, res);
 
         // Clear the notification (if received) and re-register interest in it.
         while (&self.read_stream).read(&mut [0; 64]).is_ok() {}
@@ -173,7 +173,7 @@ 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);
+        tracing::trace!("notify: kqueue_fd={}", self.kqueue_fd);
         let _ = (&self.write_stream).write(&[1]);
         Ok(())
     }
@@ -195,7 +195,7 @@ impl AsFd for Poller {
 
 impl Drop for Poller {
     fn drop(&mut self) {
-        log::trace!("drop: kqueue_fd={}", self.kqueue_fd);
+        tracing::trace!("drop: kqueue_fd={}", self.kqueue_fd);
         let _ = self.delete(self.read_stream.as_raw_fd());
         let _ = syscall!(close(self.kqueue_fd));
     }

src/lib.rs

@@ -396,7 +396,8 @@ impl Poller {
     /// # std::io::Result::Ok(())
     /// ```
     pub fn wait(&self, events: &mut Vec<Event>, timeout: Option<Duration>) -> io::Result<usize> {
-        log::trace!("Poller::wait(_, {:?})", timeout);
+        let span = tracing::trace_span!("Poller::wait", timeout = ?timeout);
+        let _enter = span.enter();
 
         if let Ok(mut lock) = self.events.try_lock() {
             // Wait for I/O events.
@@ -410,7 +411,7 @@ impl Poller {
             events.extend(lock.iter().filter(|ev| ev.key != usize::MAX));
             Ok(events.len() - len)
         } else {
-            log::trace!("wait: skipping because another thread is already waiting on I/O");
+            tracing::trace!("wait: skipping because another thread is already waiting on I/O");
             Ok(0)
         }
     }
@@ -438,7 +439,9 @@ impl Poller {
     /// # std::io::Result::Ok(())
     /// ```
     pub fn notify(&self) -> io::Result<()> {
-        log::trace!("Poller::notify()");
+        let span = tracing::trace_span!("Poller::notify");
+        let _enter = span.enter();
+
         if self
             .notified
             .compare_exchange(false, true, Ordering::SeqCst, Ordering::SeqCst)

src/poll.rs

@@ -94,7 +94,7 @@ impl Poller {
             notify_read_flags | libc::O_NONBLOCK
         ))?;
 
-        log::trace!(
+        tracing::trace!(
             "new: notify_read={}, notify_write={}",
             notify_pipe[0],
             notify_pipe[1]
@@ -123,7 +123,7 @@ impl Poller {
             return Err(io::Error::from(io::ErrorKind::InvalidInput));
         }
 
-        log::trace!(
+        tracing::trace!(
             "add: notify_read={}, fd={}, ev={:?}",
             self.notify_read,
             fd,
@@ -156,7 +156,7 @@ impl Poller {
 
     /// Modifies an existing file descriptor.
     pub fn modify(&self, fd: RawFd, ev: Event) -> io::Result<()> {
-        log::trace!(
+        tracing::trace!(
             "modify: notify_read={}, fd={}, ev={:?}",
             self.notify_read,
             fd,
@@ -175,7 +175,7 @@ impl Poller {
 
     /// Deletes a file descriptor.
     pub fn delete(&self, fd: RawFd) -> io::Result<()> {
-        log::trace!("delete: notify_read={}, fd={}", self.notify_read, fd);
+        tracing::trace!("delete: notify_read={}, fd={}", self.notify_read, fd);
 
         self.modify_fds(|fds| {
             let data = fds.fd_data.remove(&fd).ok_or(io::ErrorKind::NotFound)?;
@@ -193,7 +193,7 @@ 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!(
+        tracing::trace!(
             "wait: notify_read={}, timeout={:?}",
             self.notify_read,
             timeout
@@ -223,7 +223,7 @@ impl Poller {
             let num_events = poll(&mut fds.poll_fds, deadline)?;
             let notified = fds.poll_fds[0].0.revents != 0;
             let num_fd_events = if notified { num_events - 1 } else { num_events };
-            log::trace!(
+            tracing::trace!(
                 "new events: notify_read={}, num={}",
                 self.notify_read,
                 num_events
@@ -275,7 +275,7 @@ impl Poller {
 
     /// Sends a notification to wake up the current or next `wait()` call.
     pub fn notify(&self) -> io::Result<()> {
-        log::trace!("notify: notify_read={}", self.notify_read);
+        tracing::trace!("notify: notify_read={}", self.notify_read);
 
         if !self.notified.swap(true, Ordering::SeqCst) {
             self.notify_inner()?;
@@ -299,7 +299,7 @@ impl Poller {
             let _ = self.pop_notification();
         }
 
-        let res = f(&mut *fds);
+        let res = f(&mut fds);
 
         if self.waiting_operations.fetch_sub(1, Ordering::SeqCst) == 1 {
             self.operations_complete.notify_one();
@@ -323,7 +323,7 @@ impl Poller {
 
 impl Drop for Poller {
     fn drop(&mut self) {
-        log::trace!("drop: notify_read={}", self.notify_read);
+        tracing::trace!("drop: notify_read={}", self.notify_read);
         let _ = syscall!(close(self.notify_read));
         let _ = syscall!(close(self.notify_write));
     }

src/port.rs

@@ -48,6 +48,11 @@ impl Poller {
             },
         )?;
 
+        tracing::trace!(
+            "new: port_fd={}, read_stream={:?}",
+            port_fd,
+            poller.read_stream
+        );
         Ok(poller)
     }
 
@@ -59,6 +64,10 @@ impl Poller {
 
     /// Modifies an existing file descriptor.
     pub fn modify(&self, fd: RawFd, ev: Event) -> io::Result<()> {
+        if fd != self.read_stream.as_raw_fd() {
+            tracing::trace!("modify: port_fd={}, fd={}, ev={:?}", self.port_fd, fd, ev);
+        }
+
         let mut flags = 0;
         if ev.readable {
             flags |= libc::POLLIN;
@@ -79,6 +88,10 @@ impl Poller {
 
     /// Deletes a file descriptor.
     pub fn delete(&self, fd: RawFd) -> io::Result<()> {
+        if fd != self.read_stream.as_raw_fd() {
+            tracing::trace!("delete: port_fd={}, fd={}", self.port_fd, fd);
+        }
+
         if let Err(e) = syscall!(port_dissociate(
             self.port_fd,
             libc::PORT_SOURCE_FD,
@@ -95,6 +108,8 @@ impl Poller {
 
     /// Waits for I/O events with an optional timeout.
     pub fn wait(&self, events: &mut Events, timeout: Option<Duration>) -> io::Result<()> {
+        tracing::trace!("wait: port_fd={}, timeout={:?}", self.port_fd, timeout);
+
         let mut timeout = timeout.map(|t| libc::timespec {
             tv_sec: t.as_secs() as libc::time_t,
             tv_nsec: t.subsec_nanos() as libc::c_long,
@@ -123,6 +138,7 @@ impl Poller {
             },
             Ok(_) => nget as usize,
         };
+        tracing::trace!("new events: port_fd={}, nevents={}", self.port_fd, nevents);
         events.len = nevents;
 
         // Clear the notification (if received) and re-register interest in it.
@@ -141,6 +157,7 @@ impl Poller {
 
     /// Sends a notification to wake up the current or next `wait()` call.
     pub fn notify(&self) -> io::Result<()> {
+        tracing::trace!("notify: port_fd={}", self.port_fd);
         let _ = (&self.write_stream).write(&[1]);
         Ok(())
     }
@@ -162,6 +179,7 @@ impl AsFd for Poller {
 
 impl Drop for Poller {
     fn drop(&mut self) {
+        tracing::trace!("drop: port_fd={}", self.port_fd);
         let _ = self.delete(self.read_stream.as_raw_fd());
         let _ = syscall!(close(self.port_fd));
     }

src/wepoll.rs

@@ -54,19 +54,19 @@ impl Poller {
             ));
         }
         let notified = AtomicBool::new(false);
-        log::trace!("new: handle={:?}", handle);
+        tracing::trace!("new: handle={:?}", handle);
         Ok(Poller { handle, notified })
     }
 
     /// Adds a socket.
     pub fn add(&self, sock: RawSocket, ev: Event) -> io::Result<()> {
-        log::trace!("add: handle={:?}, sock={}, ev={:?}", self.handle, sock, ev);
+        tracing::trace!("add: handle={:?}, sock={}, ev={:?}", self.handle, sock, ev);
         self.ctl(we::EPOLL_CTL_ADD, sock, Some(ev))
     }
 
     /// Modifies a socket.
     pub fn modify(&self, sock: RawSocket, ev: Event) -> io::Result<()> {
-        log::trace!(
+        tracing::trace!(
             "modify: handle={:?}, sock={}, ev={:?}",
             self.handle,
             sock,
@@ -77,7 +77,7 @@ impl Poller {
 
     /// Deletes a socket.
     pub fn delete(&self, sock: RawSocket) -> io::Result<()> {
-        log::trace!("remove: handle={:?}, sock={}", self.handle, sock);
+        tracing::trace!("remove: handle={:?}, sock={}", self.handle, sock);
         self.ctl(we::EPOLL_CTL_DEL, sock, None)
     }
 
@@ -88,7 +88,7 @@ impl Poller {
     /// If a notification occurs, this method will return but the notification event will not be
     /// included in the `events` list nor contribute to the returned count.
     pub fn wait(&self, events: &mut Events, timeout: Option<Duration>) -> io::Result<()> {
-        log::trace!("wait: handle={:?}, timeout={:?}", self.handle, timeout);
+        tracing::trace!("wait: handle={:?}, timeout={:?}", self.handle, timeout);
         let deadline = timeout.map(|t| Instant::now() + t);
 
         loop {
@@ -112,7 +112,7 @@ impl Poller {
                 events.list.len() as c_int,
                 timeout_ms,
             ))? as usize;
-            log::trace!("new events: handle={:?}, len={}", self.handle, events.len);
+            tracing::trace!("new events: handle={:?}, len={}", self.handle, events.len);
 
             // Break if there was a notification or at least one event, or if deadline is reached.
             if self.notified.swap(false, Ordering::SeqCst) || events.len > 0 || timeout_ms == 0 {
@@ -125,7 +125,7 @@ impl Poller {
 
     /// Sends a notification to wake up the current or next `wait()` call.
     pub fn notify(&self) -> io::Result<()> {
-        log::trace!("notify: handle={:?}", self.handle);
+        tracing::trace!("notify: handle={:?}", self.handle);
 
         if self
             .notified
@@ -194,7 +194,7 @@ impl AsHandle for Poller {
 
 impl Drop for Poller {
     fn drop(&mut self) {
-        log::trace!("drop: handle={:?}", self.handle);
+        tracing::trace!("drop: handle={:?}", self.handle);
         unsafe {
             we::epoll_close(self.handle);
         }