feat(log): improve quality of debug level logs

This commit is contained in:
Sean McArthur
2017-12-08 14:49:51 -08:00
parent a594341701
commit 7b5931122a
6 changed files with 77 additions and 42 deletions

View File

@@ -169,6 +169,9 @@ where I: AsyncRead + AsyncWrite,
return Err(e);
}
};
debug!("incoming body is {}", decoder);
self.state.busy();
if head.expecting_continue() {
let msg = b"HTTP/1.1 100 Continue\r\n\r\n";
@@ -203,8 +206,11 @@ where I: AsyncRead + AsyncWrite,
if !slice.is_empty() {
return Ok(Async::Ready(Some(super::Chunk::from(slice))));
} else if decoder.is_eof() {
debug!("incoming body completed");
(Reading::KeepAlive, Ok(Async::Ready(None)))
} else {
trace!("decode stream unexpectedly ended");
//TODO: Should this return an UnexpectedEof?
(Reading::Closed, Ok(Async::Ready(None)))
}
@@ -240,10 +246,12 @@ where I: AsyncRead + AsyncWrite,
assert!(!self.can_read_head() && !self.can_read_body());
if !self.io.read_buf().is_empty() {
debug!("received an unexpected {} bytes", self.io.read_buf().len());
Err(io::Error::new(io::ErrorKind::InvalidData, "unexpected bytes after message ended"))
} else {
match self.io.read_from_io() {
Ok(Async::Ready(0)) => {
trace!("try_empty_read; found EOF on connection");
self.state.close_read();
let must_error = !self.state.is_idle() && T::should_error_on_parse_eof();
if must_error {
@@ -252,11 +260,11 @@ where I: AsyncRead + AsyncWrite,
Ok(())
}
},
Ok(Async::Ready(_)) => {
Ok(Async::Ready(n)) => {
debug!("received {} bytes on an idle connection", n);
Err(io::Error::new(io::ErrorKind::InvalidData, "unexpected bytes after message ended"))
},
Ok(Async::NotReady) => {
trace!("try_empty_read; read blocked");
Ok(())
},
Err(e) => {
@@ -616,7 +624,7 @@ where I: AsyncRead + AsyncWrite + 'static,
K: KeepAlive + 'static,
T::Outgoing: fmt::Debug {}
impl<I, B: AsRef<[u8]>, T, K: fmt::Debug> fmt::Debug for Conn<I, B, T, K> {
impl<I, B: AsRef<[u8]>, T, K: KeepAlive> fmt::Debug for Conn<I, B, T, K> {
fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
f.debug_struct("Conn")
.field("state", &self.state)
@@ -650,13 +658,13 @@ enum Writing<B> {
Closed,
}
impl<B: AsRef<[u8]>, K: fmt::Debug> fmt::Debug for State<B, K> {
impl<B: AsRef<[u8]>, K: KeepAlive> fmt::Debug for State<B, K> {
fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
f.debug_struct("State")
.field("reading", &self.reading)
.field("writing", &self.writing)
.field("keep_alive", &self.keep_alive)
.field("method", &self.method)
.field("keep_alive", &self.keep_alive.status())
//.field("method", &self.method)
.field("read_task", &self.read_task)
.finish()
}

View File

@@ -1,3 +1,4 @@
use std::fmt;
use std::usize;
use std::io;
@@ -11,26 +12,12 @@ use self::Kind::{Length, Chunked, Eof};
///
/// If a message body does not include a Transfer-Encoding, it *should*
/// include a Content-Length header.
#[derive(Debug, Clone, PartialEq)]
#[derive(Clone, PartialEq)]
pub struct Decoder {
kind: Kind,
}
impl Decoder {
pub fn length(x: u64) -> Decoder {
Decoder { kind: Kind::Length(x) }
}
pub fn chunked() -> Decoder {
Decoder { kind: Kind::Chunked(ChunkedState::Size, 0) }
}
pub fn eof() -> Decoder {
Decoder { kind: Kind::Eof(false) }
}
}
#[derive(Debug, Clone, PartialEq)]
#[derive(Debug, Clone, Copy, PartialEq)]
enum Kind {
/// A Reader used when a Content-Length header is passed with a positive integer.
Length(u64),
@@ -38,6 +25,8 @@ enum Kind {
Chunked(ChunkedState, u64),
/// A Reader used for responses that don't indicate a length or chunked.
///
/// The bool tracks when EOF is seen on the transport.
///
/// Note: This should only used for `Response`s. It is illegal for a
/// `Request` to be made with both `Content-Length` and
/// `Transfer-Encoding: chunked` missing, as explained from the spec:
@@ -53,7 +42,7 @@ enum Kind {
Eof(bool),
}
#[derive(Debug, PartialEq, Clone)]
#[derive(Debug, PartialEq, Clone, Copy)]
enum ChunkedState {
Size,
SizeLws,
@@ -68,6 +57,22 @@ enum ChunkedState {
}
impl Decoder {
// constructors
pub fn length(x: u64) -> Decoder {
Decoder { kind: Kind::Length(x) }
}
pub fn chunked() -> Decoder {
Decoder { kind: Kind::Chunked(ChunkedState::Size, 0) }
}
pub fn eof() -> Decoder {
Decoder { kind: Kind::Eof(false) }
}
// methods
pub fn is_eof(&self) -> bool {
trace!("is_eof? {:?}", self);
match self.kind {
@@ -77,9 +82,7 @@ impl Decoder {
_ => false,
}
}
}
impl Decoder {
pub fn decode<R: MemRead>(&mut self, body: &mut R) -> Poll<Bytes, io::Error> {
match self.kind {
Length(ref mut remaining) => {
@@ -131,6 +134,23 @@ impl Decoder {
}
}
impl fmt::Debug for Decoder {
fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
fmt::Debug::fmt(&self.kind, f)
}
}
impl fmt::Display for Decoder {
fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
match self.kind {
Kind::Length(n) => write!(f, "content-length ({} bytes)", n),
Kind::Chunked(..) => f.write_str("chunked encoded"),
Kind::Eof(..) => f.write_str("until end-of-file"),
}
}
}
macro_rules! byte (
($rdr:ident) => ({
let buf = try_ready!($rdr.read_mem(1));
@@ -154,7 +174,7 @@ impl ChunkedState {
Size => ChunkedState::read_size(body, size),
SizeLws => ChunkedState::read_size_lws(body),
Extension => ChunkedState::read_extension(body),
SizeLf => ChunkedState::read_size_lf(body, size),
SizeLf => ChunkedState::read_size_lf(body, *size),
Body => ChunkedState::read_body(body, size, buf),
BodyCr => ChunkedState::read_body_cr(body),
BodyLf => ChunkedState::read_body_lf(body),
@@ -209,11 +229,17 @@ impl ChunkedState {
_ => Ok(Async::Ready(ChunkedState::Extension)), // no supported extensions
}
}
fn read_size_lf<R: MemRead>(rdr: &mut R, size: &mut u64) -> Poll<ChunkedState, io::Error> {
fn read_size_lf<R: MemRead>(rdr: &mut R, size: u64) -> Poll<ChunkedState, io::Error> {
trace!("Chunk size is {:?}", size);
match byte!(rdr) {
b'\n' if *size > 0 => Ok(Async::Ready(ChunkedState::Body)),
b'\n' if *size == 0 => Ok(Async::Ready(ChunkedState::EndCr)),
b'\n' => {
if size == 0 {
Ok(Async::Ready(ChunkedState::EndCr))
} else {
debug!("incoming chunked header: {0:#X} ({0} bytes)", size);
Ok(Async::Ready(ChunkedState::Body))
}
},
_ => Err(io::Error::new(io::ErrorKind::InvalidInput, "Invalid chunk size LF")),
}
}

View File

@@ -70,9 +70,9 @@ impl<T: AsyncRead + AsyncWrite> Buffered<T> {
pub fn parse<S: Http1Transaction>(&mut self) -> Poll<MessageHead<S::Incoming>, ::Error> {
loop {
match try!(S::parse(&mut self.read_buf)) {
Some(head) => {
//trace!("parsed {} bytes out of {}", len, self.read_buf.len());
return Ok(Async::Ready(head.0))
Some((head, len)) => {
debug!("parsed {} headers ({} bytes)", head.headers.len(), len);
return Ok(Async::Ready(head))
},
None => {
if self.read_buf.capacity() >= MAX_BUFFER_SIZE {
@@ -118,6 +118,7 @@ impl<T: AsyncRead + AsyncWrite> Buffered<T> {
return Err(e)
}
};
debug!("read {} bytes", n);
self.read_buf.advance_mut(n);
Ok(Async::Ready(n))
}
@@ -154,7 +155,7 @@ impl<T: Write> Write for Buffered<T> {
} else {
loop {
let n = try!(self.write_buf.write_into(&mut self.io));
trace!("flushed {} bytes", n);
debug!("flushed {} bytes", n);
if self.write_buf.remaining() == 0 {
break;
}