test: more tracing

Author: aatifsyed

Cargo.toml

@@ -55,6 +55,8 @@ proptest-derive = "0.5"
 rand = "0.8.5"
 tokio = { version = "1.24.2", default-features = false, features = ["io-util", "macros", "rt-multi-thread", "io-std"] }
 tokio-util = { version = "0.7", default-features = false, features = ["io"] }
+tracing = "0.1.40"
+tracing-subscriber = "0.3.18"
 
 [[test]]
 name = "brotli"

tests/issues.rs

@@ -1,18 +1,26 @@
 #![cfg(all(feature = "tokio", feature = "zstd"))]
-#![allow(clippy::unusual_byte_groupings)]
 
 use std::{
     io,
     pin::Pin,
-    task::{Context, Poll},
+    task::{ready, Context, Poll},
 };
 
 use async_compression::tokio::write::ZstdEncoder;
 use tokio::io::{AsyncWrite, AsyncWriteExt as _};
+use tracing_subscriber::fmt::format::FmtSpan;
 
 /// <https://github.com/Nullus157/async-compression/issues/246>
 #[tokio::test]
 async fn issue_246() {
+    tracing_subscriber::fmt()
+        .without_time()
+        .with_ansi(false)
+        .with_level(false)
+        .with_test_writer()
+        .with_target(false)
+        .with_span_events(FmtSpan::NEW)
+        .init();
     let mut zstd_encoder =
         Transparent::new(Trace::new(ZstdEncoder::new(DelayedShutdown::default())));
     zstd_encoder.shutdown().await.unwrap();
@@ -32,39 +40,30 @@ impl<T> Transparent<T> {
 }
 
 impl<T: AsyncWrite> AsyncWrite for Transparent<T> {
+    #[tracing::instrument(name = "Transparent::poll_write", skip_all, ret)]
     fn poll_write(
         self: Pin<&mut Self>,
         cx: &mut Context<'_>,
         buf: &[u8],
     ) -> Poll<Result<usize, io::Error>> {
-        eprintln!("Transparent::poll_write = ...");
-        let ret = self.project().inner.poll_write(cx, buf);
-        eprintln!("Transparent::poll_write = {:?}", ret);
-        ret
+        self.project().inner.poll_write(cx, buf)
     }
 
+    #[tracing::instrument(name = "Transparent::poll_flush", skip_all, ret)]
     fn poll_flush(self: Pin<&mut Self>, cx: &mut Context<'_>) -> Poll<Result<(), io::Error>> {
-        eprintln!("Transparent::poll_flush = ...");
-        let ret = self.project().inner.poll_flush(cx);
-        eprintln!("Transparent::poll_flush = {:?}", ret);
-        ret
+        self.project().inner.poll_flush(cx)
     }
 
     /// To quote the [`AsyncWrite`] docs:
     /// > Invocation of a shutdown implies an invocation of flush.
     /// > Once this method returns Ready it implies that a flush successfully happened before the shutdown happened.
     /// > That is, callers don't need to call flush before calling shutdown.
     /// > They can rely that by calling shutdown any pending buffered data will be written out.
+    #[tracing::instrument(name = "Transparent::poll_shutdown", skip_all, ret)]
     fn poll_shutdown(self: Pin<&mut Self>, cx: &mut Context<'_>) -> Poll<Result<(), io::Error>> {
-        eprintln!("Transparent::poll_shutdown = ...");
         let mut this = self.project();
-        let ret = match this.inner.as_mut().poll_flush(cx) {
-            Poll::Ready(Ok(())) => this.inner.poll_shutdown(cx),
-            Poll::Ready(Err(e)) => Poll::Ready(Err(e)),
-            Poll::Pending => Poll::Pending,
-        };
-        eprintln!("Transparent::poll_shutdown = {:?}", ret);
-        ret
+        ready!(this.inner.as_mut().poll_flush(cx))?;
+        this.inner.poll_shutdown(cx)
     }
 }
 
@@ -78,39 +77,33 @@ pin_project_lite::pin_project! {
 }
 
 impl AsyncWrite for DelayedShutdown {
+    #[tracing::instrument(name = "DelayedShutdown::poll_write", skip_all, ret)]
     fn poll_write(
         self: Pin<&mut Self>,
         cx: &mut Context<'_>,
         buf: &[u8],
     ) -> Poll<Result<usize, io::Error>> {
-        eprintln!("DelayedShutdown::poll_write = ...");
         let _ = cx;
         self.project().contents.extend_from_slice(buf);
-        let ret = Poll::Ready(Ok(buf.len()));
-        eprintln!("DelayedShutdown::poll_write = {:?}", ret);
-        ret
+        Poll::Ready(Ok(buf.len()))
     }
 
+    #[tracing::instrument(name = "DelayedShutdown::poll_flush", skip_all, ret)]
     fn poll_flush(self: Pin<&mut Self>, cx: &mut Context<'_>) -> Poll<Result<(), io::Error>> {
-        eprintln!("DelayedShutdown::poll_flush = ...");
         let _ = cx;
-        let ret = Poll::Ready(Ok(()));
-        eprintln!("DelayedShutdown::poll_flush = {:?}", ret);
-        ret
+        Poll::Ready(Ok(()))
     }
 
+    #[tracing::instrument(name = "DelayedShutdown::poll_shutdown", skip_all, ret)]
     fn poll_shutdown(self: Pin<&mut Self>, cx: &mut Context<'_>) -> Poll<Result<(), io::Error>> {
-        eprintln!("DelayedShutdown::poll_shutdown = ...");
-        let ret = match self.project().num_times_shutdown_called {
+        match self.project().num_times_shutdown_called {
             it @ 0 => {
                 *it += 1;
                 cx.waker().wake_by_ref();
                 Poll::Pending
             }
             _ => Poll::Ready(Ok(())),
-        };
-        eprintln!("DelayedShutdown::poll_shutdown = {:?}", ret);
-        ret
+        }
     }
 }
 
@@ -128,28 +121,21 @@ impl<T> Trace<T> {
 }
 
 impl<T: AsyncWrite> AsyncWrite for Trace<T> {
+    #[tracing::instrument(name = "Trace::poll_write", skip_all, ret)]
     fn poll_write(
         self: Pin<&mut Self>,
         cx: &mut Context<'_>,
         buf: &[u8],
     ) -> Poll<Result<usize, io::Error>> {
-        eprintln!("Trace::poll_write = ...");
-        let ret = self.project().inner.poll_write(cx, buf);
-        eprintln!("Trace::poll_write = {:?}", ret);
-        ret
+        self.project().inner.poll_write(cx, buf)
     }
-
+    #[tracing::instrument(name = "Trace::poll_flush", skip_all, ret)]
     fn poll_flush(self: Pin<&mut Self>, cx: &mut Context<'_>) -> Poll<Result<(), io::Error>> {
-        eprintln!("Trace::poll_flush = ...");
-        let ret = self.project().inner.poll_flush(cx);
-        eprintln!("Trace::poll_flush = {:?}", ret);
-        ret
+        self.project().inner.poll_flush(cx)
     }
 
+    #[tracing::instrument(name = "Trace::poll_shutdown", skip_all, ret)]
     fn poll_shutdown(self: Pin<&mut Self>, cx: &mut Context<'_>) -> Poll<Result<(), io::Error>> {
-        eprintln!("Trace::poll_shutdown = ...");
-        let ret = self.project().inner.poll_shutdown(cx);
-        eprintln!("Trace::poll_shutdown = {:?}", ret);
-        ret
+        self.project().inner.poll_shutdown(cx)
     }
 }