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.
This commit is contained in:
Eliza Weisman 2018-04-05 13:47:19 -07:00 committed by GitHub
parent 49bf01b0da
commit 18fa42ebd0
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
1 changed files with 32 additions and 5 deletions

View File

@ -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)
}
}