From 18fa42ebd05e25ffec8865b60999a797eedca32c Mon Sep 17 00:00:00 2001
From: Eliza Weisman <eliza@buoyant.io>
Date: Thu, 5 Apr 2018 13:47:19 -0700
Subject: [PATCH] Pretty-print durations in log messages (#676)

This branch adds simple pretty-printing to duration in log timeout messages. If the duration is >= 1 second, it's printed in seconds with a fractional part. If the duration is less than 1 second, it is printed in milliseconds. This simple formatting may not be sufficient as a formatting rule for all cases, but should be sufficient for printing our relatively small timeouts.

Log messages now look something like this:
```
ERROR 2018-04-04T20:05:49Z: conduit_proxy: turning operation timed out after 100 ms into 500
```

Previously, they looked like this:
```
ERROR 2018-04-04T20:07:26Z: conduit_proxy: turning operation timed out after Duration { secs: 0, nanos: 100000000 } into 500
```

I made this change partially because I wanted to make the panics from the `eventually!` macro added in #669 more readable.
---
 proxy/src/timeout.rs | 37 ++++++++++++++++++++++++++++++++-----
 1 file changed, 32 insertions(+), 5 deletions(-)

diff --git a/proxy/src/timeout.rs b/proxy/src/timeout.rs
index ecc2fb0fd..351bc1497 100644
--- a/proxy/src/timeout.rs
+++ b/proxy/src/timeout.rs
@@ -2,8 +2,7 @@
 use futures::{Async, Future, Poll};
 
 use std::error::Error;
-use std::fmt;
-use std::io;
+use std::{fmt, io};
 use std::time::Duration;
 
 use tokio_connect::Connect;
@@ -35,6 +34,13 @@ pub struct TimeoutFuture<F> {
     timeout: ReactorTimeout,
 }
 
+/// A duration which pretty-prints as fractional seconds.
+///
+/// This may not be the ideal display format for _all_ duration values,
+/// but should be sufficient for most timeouts.
+#[derive(Copy, Clone, Debug)]
+pub struct HumanDuration(pub Duration);
+
 //===== impl Timeout =====
 
 impl<U> Timeout<U> {
@@ -152,9 +158,8 @@ where
 {
     fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
         match *self {
-            TimeoutError::Timeout(ref duration) =>
-                // TODO: format the duration nicer.
-                write!(f, "operation timed out after {:?}", duration),
+            TimeoutError::Timeout(ref d) =>
+                write!(f, "operation timed out after {}", HumanDuration(*d)),
             TimeoutError::Error(ref err) => fmt::Display::fmt(err, f),
         }
     }
@@ -212,3 +217,25 @@ where
            .finish()
     }
 }
+
+//===== impl HumanDuration =====
+
+impl fmt::Display for HumanDuration {
+    fn fmt(&self, fmt: &mut fmt::Formatter) -> fmt::Result {
+        let secs = self.0.as_secs();
+        let subsec_ms = self.0.subsec_nanos() as f64 / 1_000_000f64;
+        if secs == 0 {
+            write!(fmt, "{}ms", subsec_ms)
+        } else {
+            write!(fmt, "{}s", secs as f64 + subsec_ms)
+        }
+    }
+}
+
+impl From<Duration> for HumanDuration {
+
+    #[inline]
+    fn from(d: Duration) -> Self {
+        HumanDuration(d)
+    }
+}