buffered-reader: Add tracing.

2 files changed, 77 insertions, 7 deletions

diff --git a/buffered-reader/src/generic.rs b/buffered-reader/src/generic.rs
index f54fe6b2..7dec14e1 100644
--- a/buffered-reader/src/generic.rs
+++ b/buffered-reader/src/generic.rs
@@ -5,6 +5,9 @@ use std::io::{Error, ErrorKind};
 
 use super::*;
 
+/// Controls tracing.
+const TRACE: bool = false;
+
 /// Wraps a `Read`er.
 ///
 /// This is useful when reading from a generic `std::io::Read`er.  To
@@ -107,16 +110,15 @@ impl<T: io::Read + Send + Sync, C: fmt::Debug + Sync + Send> Generic<T, C> {
     // sequoia_openpgp::armor::Reader::data_helper is also affected.
     fn data_helper(&mut self, amount: usize, hard: bool, and_consume: bool)
                    -> Result<&[u8], io::Error> {
-        // println!("Generic.data_helper(\
-        //           amount: {}, hard: {}, and_consume: {} (cursor: {}, buffer: {:?})",
-        //          amount, hard, and_consume,
-        //          self.cursor,
-        //          if let Some(ref buffer) = self.buffer { Some(buffer.len()) }
-        //          else { None });
-
+        tracer!(TRACE, "Generic::data_helper");
+        t!("amount: {}, hard: {}, and_consume: {} (cursor: {}, buffer: {:?})",
+           amount, hard, and_consume,
+           self.cursor,
+           self.buffer.as_ref().map(|buffer| buffer.len()));
 
         // See if there is an error from the last invocation.
         if let Some(e) = self.error.take() {
+            t!("Returning stashed error: {}", e);
             return Err(e);
         }
 
@@ -147,9 +149,12 @@ impl<T: io::Read + Send + Sync, C: fmt::Debug + Sync + Send> Generic<T, C> {
 
             let mut amount_read = 0;
             while amount_buffered + amount_read < amount {
+                t!("Have {} bytes, need {} bytes",
+                   amount_buffered + amount_read, amount);
                 match self.reader.read(&mut buffer_new
                                        [amount_buffered + amount_read..]) {
                     Ok(read) => {
+                        t!("Read {} bytes", read);
                         if read == 0 {
                             break;
                         } else {
@@ -189,19 +194,24 @@ impl<T: io::Read + Send + Sync, C: fmt::Debug + Sync + Send> Generic<T, C> {
             = self.buffer.as_ref().map(|b| b.len() - self.cursor).unwrap_or(0);
 
         if self.error.is_some() {
+            t!("Encountered an error: {}", self.error.as_ref().unwrap());
             // An error occurred.  If we have enough data to fulfill
             // the caller's request, then don't return the error.
             if hard && amount > amount_buffered {
+                t!("Not enough data to fulfill request, returning error");
                 return Err(self.error.take().unwrap());
             }
             if !hard && amount_buffered == 0 {
+                t!("No data data buffered, returning error");
                 return Err(self.error.take().unwrap());
             }
         }
 
         if hard && amount_buffered < amount {
+            t!("Unexpected EOF");
             Err(Error::new(ErrorKind::UnexpectedEof, "EOF"))
         } else if amount == 0 || amount_buffered == 0 {
+            t!("Returning zero-length slice");
             Ok(&b""[..])
         } else {
             let buffer = self.buffer.as_ref().unwrap();
@@ -209,8 +219,13 @@ impl<T: io::Read + Send + Sync, C: fmt::Debug + Sync + Send> Generic<T, C> {
                 let amount_consumed = cmp::min(amount_buffered, amount);
                 self.cursor += amount_consumed;
                 assert!(self.cursor <= buffer.len());
+                t!("Consuming {} bytes, returning {} bytes",
+                   amount_consumed,
+                   buffer[self.cursor-amount_consumed..].len());
                 Ok(&buffer[self.cursor-amount_consumed..])
             } else {
+                t!("Returning {} bytes",
+                   buffer[self.cursor..].len());
                 Ok(&buffer[self.cursor..])
             }
         }
diff --git a/buffered-reader/src/macros.rs b/buffered-reader/src/macros.rs
index d6792648..7d2142e9 100644
--- a/buffered-reader/src/macros.rs
+++ b/buffered-reader/src/macros.rs
@@ -1,3 +1,58 @@
+macro_rules! trace {
+    ( $TRACE:expr, $fmt:expr, $($pargs:expr),* ) => {
+        if $TRACE {
+            eprintln!($fmt, $($pargs),*);
+        }
+    };
+    ( $TRACE:expr, $fmt:expr ) => {
+        trace!($TRACE, $fmt, );
+    };
+}
+
+// Converts an indentation level to whitespace.
+pub(crate) fn indent(i: isize) -> &'static str {
+    use std::convert::TryFrom;
+    let s = "                                                  ";
+    &s[0..usize::try_from(i).unwrap_or(0).min(s.len())]
+}
+
+macro_rules! tracer {
+    ( $TRACE:expr, $func:expr ) => {
+        tracer!($TRACE, $func, 0)
+    };
+    ( $TRACE:expr, $func:expr, $indent:expr ) => {
+        // Currently, Rust doesn't support $( ... ) in a nested
+        // macro's definition.  See:
+        // https://users.rust-lang.org/t/nested-macros-issue/8348/2
+        macro_rules! t {
+            ( $fmt:expr ) =>
+            { trace!($TRACE, "{}{}: {}", crate::macros::indent($indent), $func, $fmt) };
+            ( $fmt:expr, $a:expr ) =>
+            { trace!($TRACE, "{}{}: {}", crate::macros::indent($indent), $func, format!($fmt, $a)) };
+            ( $fmt:expr, $a:expr, $b:expr ) =>
+            { trace!($TRACE, "{}{}: {}", crate::macros::indent($indent), $func, format!($fmt, $a, $b)) };
+            ( $fmt:expr, $a:expr, $b:expr, $c:expr ) =>
+            { trace!($TRACE, "{}{}: {}", crate::macros::indent($indent), $func, format!($fmt, $a, $b, $c)) };
+            ( $fmt:expr, $a:expr, $b:expr, $c:expr, $d:expr ) =>
+            { trace!($TRACE, "{}{}: {}", crate::macros::indent($indent), $func, format!($fmt, $a, $b, $c, $d)) };
+            ( $fmt:expr, $a:expr, $b:expr, $c:expr, $d:expr, $e:expr ) =>
+            { trace!($TRACE, "{}{}: {}", crate::macros::indent($indent), $func, format!($fmt, $a, $b, $c, $d, $e)) };
+            ( $fmt:expr, $a:expr, $b:expr, $c:expr, $d:expr, $e:expr, $f:expr ) =>
+            { trace!($TRACE, "{}{}: {}", crate::macros::indent($indent), $func, format!($fmt, $a, $b, $c, $d, $e, $f)) };
+            ( $fmt:expr, $a:expr, $b:expr, $c:expr, $d:expr, $e:expr, $f:expr, $g:expr ) =>
+            { trace!($TRACE, "{}{}: {}", crate::macros::indent($indent), $func, format!($fmt, $a, $b, $c, $d, $e, $f, $g)) };
+            ( $fmt:expr, $a:expr, $b:expr, $c:expr, $d:expr, $e:expr, $f:expr, $g:expr, $h:expr ) =>
+            { trace!($TRACE, "{}{}: {}", crate::macros::indent($indent), $func, format!($fmt, $a, $b, $c, $d, $e, $f, $g, $h)) };
+            ( $fmt:expr, $a:expr, $b:expr, $c:expr, $d:expr, $e:expr, $f:expr, $g:expr, $h:expr, $i:expr ) =>
+            { trace!($TRACE, "{}{}: {}", crate::macros::indent($indent), $func, format!($fmt, $a, $b, $c, $d, $e, $f, $g, $h, $i)) };
+            ( $fmt:expr, $a:expr, $b:expr, $c:expr, $d:expr, $e:expr, $f:expr, $g:expr, $h:expr, $i:expr, $j:expr ) =>
+            { trace!($TRACE, "{}{}: {}", crate::macros::indent($indent), $func, format!($fmt, $a, $b, $c, $d, $e, $f, $g, $h, $i, $j)) };
+            ( $fmt:expr, $a:expr, $b:expr, $c:expr, $d:expr, $e:expr, $f:expr, $g:expr, $h:expr, $i:expr, $j:expr, $k:expr ) =>
+            { trace!($TRACE, "{}{}: {}", crate::macros::indent($indent), $func, format!($fmt, $a, $b, $c, $d, $e, $f, $g, $h, $i, $j, $k)) };
+        }
+    }
+}
+
 /// A simple shortcut for ensuring a type is send and sync.
 ///
 /// For most types just call it after defining the type: