refactor logger middleware

README.md

@@ -134,7 +134,7 @@ fn main() {
     HttpServer::new(
         Application::default("/")
             // enable logger
-            .middleware(middlewares::Logger::new(None))
+            .middleware(middlewares::Logger::default())
             // websocket route
             .resource("/ws/", |r| r.get::<MyWebSocket>())
             .route_handler("/", StaticFiles::new("examples/static/", true)))

examples/basic.rs

@@ -49,7 +49,7 @@ fn main() {
     HttpServer::new(
         Application::default("/")
             // enable logger
-            .middleware(middlewares::Logger::new(None))
+            .middleware(middlewares::Logger::default())
             // register simple handle r, handle all methods
             .handler("/index.html", index)
             // with path parameters

examples/state.rs

@@ -74,7 +74,7 @@ fn main() {
     HttpServer::new(
         Application::builder("/", AppState{counter: Cell::new(0)})
             // enable logger
-            .middleware(middlewares::Logger::new(None))
+            .middleware(middlewares::Logger::default())
             // websocket route
             .resource("/ws/", |r| r.get::<MyWebSocket>())
             // register simple handler, handle all methods

examples/tls/src/main.rs

@@ -32,7 +32,7 @@ fn main() {
     HttpServer::new(
         Application::default("/")
             // enable logger
-            .middleware(middlewares::Logger::new(None))
+            .middleware(middlewares::Logger::default())
             // register simple handler, handle all methods
             .handler("/index.html", index)
             // with path parameters

examples/websocket.rs

@@ -73,7 +73,7 @@ fn main() {
     HttpServer::new(
         Application::default("/")
             // enable logger
-            .middleware(middlewares::Logger::new(None))
+            .middleware(middlewares::Logger::default())
             // websocket route
             .resource("/ws/", |r| r.get::<MyWebSocket>())
             .route_handler("/", StaticFiles::new("examples/static/", true)))

src/h1.rs

@@ -498,11 +498,9 @@ impl Reader {
 
         let (len, method, path, version, headers_len) = {
             let mut headers = [httparse::EMPTY_HEADER; MAX_HEADERS];
-            trace!("Request.parse([Header; {}], [u8; {}])", headers.len(), buf.len());
             let mut req = httparse::Request::new(&mut headers);
             match try!(req.parse(buf)) {
                 httparse::Status::Complete(len) => {
-                    trace!("Request.parse Complete({})", len);
                     let method = Method::try_from(req.method.unwrap())
                         .map_err(|_| ParseError::Method)?;
                     let path = req.path.unwrap();

src/h1writer.rs

@@ -23,6 +23,8 @@ pub(crate) enum WriterState {
 
 /// Send stream
 pub(crate) trait Writer {
+    fn written(&self) -> u64;
+
     fn start(&mut self, req: &mut HttpRequest, resp: &mut HttpResponse)
              -> Result<WriterState, io::Error>;
 
@@ -41,6 +43,8 @@ pub(crate) struct H1Writer<T: AsyncWrite> {
     upgrade: bool,
     keepalive: bool,
     disconnected: bool,
+    written: u64,
+    headers_size: u64,
 }
 
 impl<T: AsyncWrite> H1Writer<T> {
@@ -53,6 +57,8 @@ impl<T: AsyncWrite> H1Writer<T> {
             upgrade: false,
             keepalive: false,
             disconnected: false,
+            written: 0,
+            headers_size: 0,
         }
     }
 
@@ -80,6 +86,7 @@ impl<T: AsyncWrite> H1Writer<T> {
                 match stream.write(buffer.as_ref()) {
                     Ok(n) => {
                         buffer.split_to(n);
+                        self.written += n as u64;
                     },
                     Err(ref e) if e.kind() == io::ErrorKind::WouldBlock => {
                         if buffer.len() > MAX_WRITE_BUFFER_SIZE {
@@ -98,6 +105,14 @@ impl<T: AsyncWrite> H1Writer<T> {
 
 impl<T: AsyncWrite> Writer for H1Writer<T> {
 
+    fn written(&self) -> u64 {
+        if self.written > self.headers_size {
+            self.written - self.headers_size
+        } else {
+            0
+        }
+    }
+
     fn start(&mut self, req: &mut HttpRequest, msg: &mut HttpResponse)
              -> Result<WriterState, io::Error>
     {
@@ -162,6 +177,7 @@ impl<T: AsyncWrite> Writer for H1Writer<T> {
 
             // msg eof
             buffer.extend(b"\r\n");
+            self.headers_size = buffer.len() as u64;
         }
 
         trace!("Response: {:?}", msg);

src/h2writer.rs

@@ -24,6 +24,7 @@ pub(crate) struct H2Writer {
     encoder: PayloadEncoder,
     disconnected: bool,
     eof: bool,
+    written: u64,
 }
 
 impl H2Writer {
@@ -36,6 +37,7 @@ impl H2Writer {
             encoder: PayloadEncoder::default(),
             disconnected: false,
             eof: true,
+            written: 0,
         }
     }
 
@@ -76,6 +78,7 @@ impl H2Writer {
                         let len = buffer.len();
                         let bytes = buffer.split_to(cmp::min(cap, len));
                         let eof = buffer.is_empty() && self.eof;
+                        self.written += bytes.len() as u64;
 
                         if let Err(err) = stream.send_data(bytes.freeze(), eof) {
                             return Err(io::Error::new(io::ErrorKind::Other, err))
@@ -98,6 +101,10 @@ impl H2Writer {
 
 impl Writer for H2Writer {
 
+    fn written(&self) -> u64 {
+        self.written
+    }
+
     fn start(&mut self, req: &mut HttpRequest, msg: &mut HttpResponse)
              -> Result<WriterState, io::Error>
     {

src/httpresponse.rs

@@ -34,6 +34,7 @@ pub struct HttpResponse {
     encoding: ContentEncoding,
     connection_type: Option<ConnectionType>,
     error: Option<Box<Error>>,
+    response_size: u64,
 }
 
 impl HttpResponse {
@@ -59,6 +60,7 @@ impl HttpResponse {
             encoding: ContentEncoding::Auto,
             connection_type: None,
             error: None,
+            response_size: 0,
         }
     }
 
@@ -75,6 +77,7 @@ impl HttpResponse {
             encoding: ContentEncoding::Auto,
             connection_type: None,
             error: Some(Box::new(error)),
+            response_size: 0,
         }
     }
 
@@ -196,6 +199,16 @@ impl HttpResponse {
     pub fn replace_body<B: Into<Body>>(&mut self, body: B) -> Body {
         mem::replace(&mut self.body, body.into())
     }
+
+    /// Size of response in bytes, excluding HTTP headers
+    pub fn response_size(&self) -> u64 {
+        self.response_size
+    }
+
+    /// Set content encoding
+    pub(crate) fn set_response_size(&mut self, size: u64) {
+        self.response_size = size;
+    }
 }
 
 /// Helper conversion implementation
@@ -433,6 +446,7 @@ impl HttpResponseBuilder {
             encoding: parts.encoding,
             connection_type: parts.connection_type,
             error: None,
+            response_size: 0,
         })
     }
 

src/middlewares/logger.rs

@@ -1,36 +1,74 @@
 //! Request logging middleware
+use std::env;
 use std::fmt;
-use std::str::Chars;
-use std::iter::Peekable;
 use std::fmt::{Display, Formatter};
 
 use time;
+use regex::Regex;
 
 use httprequest::HttpRequest;
 use httpresponse::HttpResponse;
 use middlewares::{Middleware, Started, Finished};
 
 /// `Middleware` for logging request and response info to the terminal.
+///
+/// ## Usage
+///
+/// Create `Logger` middlewares with the specified `format`.
+/// Default `Logger` could be created with `default` method, it uses the default format:
+///
+/// ```ignore
+/// %a %t "%r" %s %b "%{Referrer}i" "%{User-Agent}i %T"
+/// ```
+/// ```rust,ignore
+///
+/// let app = Application::default("/")
+///     .middleware(Logger::default())
+///     .middleware(Logger::new("%a %{User-Agent}i"))
+///     .finish()
+/// ```
+///
+/// ## Format
+///
+/// `%%`  The percent sign
+///
+/// `%a`  Remote IP-address (IP-address of proxy if using reverse proxy)
+///
+/// `%t`  Time when the request was started to process
+///
+/// `%P`  The process ID of the child that serviced the request
+///
+/// `%r`  First line of request
+///
+/// `%s`  Response status code
+///
+/// `%b`  Size of response in bytes, including HTTP headers
+///
+/// `%T` Time taken to serve the request, in seconds with floating fraction in .06f format
+///
+/// `%D`  Time taken to serve the request, in milliseconds
+///
+/// `%{FOO}i`  request.headers['FOO']
+///
+/// `%{FOO}o`  response.headers['FOO']
+///
+/// `%{FOO}e`  os.environ['FOO']
+///
 pub struct Logger {
     format: Format,
 }
 
 impl Logger {
-    /// Create `Logger` middlewares with the specified `format`.
+    /// Create `Logger` middleware with the specified `format`.
-    /// If a `None` is passed in, uses the default format:
+    pub fn new(format: &str) -> Logger {
-    ///
+        Logger { format: Format::new(format) }
-    /// ```ignore
+    }
-    /// {method} {uri} -> {status} ({response-time} ms)
+}
-    /// ```
+
-    ///
+impl Default for Logger {
-    /// ```rust,ignore
+    /// Create default `Logger` middleware
-    /// let app = Application::default("/")
+    fn default() -> Logger {
-    ///     .middleware(Logger::new(None))
+        Logger { format: Format::default() }
-    ///     .finish()
-    /// ```
-    pub fn new(format: Option<Format>) -> Logger {
-        let format = format.unwrap_or_default();
-        Logger { format: format.clone() }
     }
 }
 
@@ -43,28 +81,58 @@ impl Logger {
 
         let response_time = time::now() - entry_time;
         let response_time_ms = (response_time.num_seconds() * 1000) as f64 +
-            (response_time.num_nanoseconds().unwrap_or(0) as f64) / 1000000000.0;
+            (response_time.num_nanoseconds().unwrap_or(0) as f64) / 1000000.0;
         {
             let render = |fmt: &mut Formatter, text: &FormatText| {
                 match *text {
                     FormatText::Str(ref string) => fmt.write_str(string),
-                    FormatText::Method => req.method().fmt(fmt),
+                    FormatText::Percent => "%".fmt(fmt),
-                    FormatText::URI => {
+                    FormatText::RequestLine => {
                         if req.query_string().is_empty() {
-                            fmt.write_fmt(format_args!("{}", req.path()))
+                            fmt.write_fmt(format_args!(
+                                "{} {} {:?}",
+                                req.method(), req.path(), req.version()))
                         } else {
-                            fmt.write_fmt(format_args!("{}?{}", req.path(), req.query_string()))
+                            fmt.write_fmt(format_args!(
+                                "{} {}?{} {:?}",
+                                req.method(), req.path(), req.query_string(), req.version()))
                         }
                     },
-                    FormatText::Status => resp.status().fmt(fmt),
+                    FormatText::ResponseStatus => resp.status().as_u16().fmt(fmt),
-                    FormatText::ResponseTime =>
+                    FormatText::ResponseSize => resp.response_size().fmt(fmt),
-                        fmt.write_fmt(format_args!("{} sec", response_time_ms)),
+                    FormatText::Time =>
+                        fmt.write_fmt(format_args!("{:.6}", response_time_ms/1000.0)),
+                    FormatText::TimeMillis =>
+                        fmt.write_fmt(format_args!("{:.6}", response_time_ms)),
                     FormatText::RemoteAddr => Ok(()), //req.remote_addr.fmt(fmt),
                     FormatText::RequestTime => {
-                        entry_time.strftime("%Y-%m-%dT%H:%M:%S.%fZ%z")
+                        entry_time.strftime("[%d/%b/%Y:%H:%M:%S %z]")
                             .unwrap()
                             .fmt(fmt)
                     }
+                    FormatText::RequestHeader(ref name) => {
+                        let s = if let Some(val) = req.headers().get(name) {
+                            if let Ok(s) = val.to_str() { s } else { "-" }
+                        } else {
+                            "-"
+                        };
+                        fmt.write_fmt(format_args!("{}", s))
+                    }
+                    FormatText::ResponseHeader(ref name) => {
+                        let s = if let Some(val) = resp.headers().get(name) {
+                            if let Ok(s) = val.to_str() { s } else { "-" }
+                        } else {
+                            "-"
+                        };
+                        fmt.write_fmt(format_args!("{}", s))
+                    }
+                    FormatText::EnvironHeader(ref name) => {
+                        if let Ok(val) = env::var(name) {
+                            fmt.write_fmt(format_args!("{}", val))
+                        } else {
+                            "-".fmt(fmt)
+                        }
+                    }
                 }
             };
 
@@ -87,46 +155,72 @@ impl Middleware for Logger {
 }
 
 
-use self::FormatText::{Method, URI, Status, ResponseTime, RemoteAddr, RequestTime};
-
 /// A formatting style for the `Logger`, consisting of multiple
 /// `FormatText`s concatenated into one line.
 #[derive(Clone)]
 #[doc(hidden)]
-pub struct Format(Vec<FormatText>);
+struct Format(Vec<FormatText>);
 
 impl Default for Format {
     /// Return the default formatting style for the `Logger`:
     ///
     /// ```ignore
-    /// {method} {uri} -> {status} ({response-time})
+    /// %a %t "%r" %s %b "%{Referrer}i" "%{User-Agent}i %T"
-    /// // This will be written as: {method} {uri} -> {status} ({response-time})
     /// ```
     fn default() -> Format {
-        Format::new("{method} {uri} {status} ({response-time})").unwrap()
+        Format::new(r#"%a %t "%r" %s %b "%{Referrer}i" "%{User-Agent}i" %T"#)
     }
 }
 
 impl Format {
-    /// Create a `Format` from a format string, which can contain the fields
+    /// Create a `Format` from a format string.
-    /// `{method}`, `{uri}`, `{status}`, `{response-time}`, `{ip-addr}` and
-    /// `{request-time}`.
     ///
     /// Returns `None` if the format string syntax is incorrect.
-    pub fn new(s: &str) -> Option<Format> {
+    pub fn new(s: &str) -> Format {
-
+        trace!("Access log format: {}", s);
-        let parser = FormatParser::new(s.chars().peekable());
+        let fmt = Regex::new(r"%(\{([A-Za-z0-9\-_]+)\}([ioe])|[atPrsbTD]?)").unwrap();
 
+        let mut idx = 0;
         let mut results = Vec::new();
+        for cap in fmt.captures_iter(s) {
+            let m = cap.get(0).unwrap();
+            let pos = m.start();
+            if idx != pos {
+                results.push(FormatText::Str(s[idx..pos].to_owned()));
+            }
+            idx = m.end();
 
-        for unit in parser {
+            if let Some(key) = cap.get(2) {
-            match unit {
+                results.push(
-                Some(unit) => results.push(unit),
+                    match cap.get(3).unwrap().as_str() {
-                None => return None
+                        "i" => FormatText::RequestHeader(key.as_str().to_owned()),
+                        "o" => FormatText::ResponseHeader(key.as_str().to_owned()),
+                        "e" => FormatText::EnvironHeader(key.as_str().to_owned()),
+                        _ => unreachable!(),
+                    })
+            } else {
+                let m = cap.get(1).unwrap();
+                results.push(
+                    match m.as_str() {
+                        "%" => FormatText::Percent,
+                        "a" => FormatText::RemoteAddr,
+                        "t" => FormatText::RequestTime,
+                        "P" => FormatText::Percent,
+                        "r" => FormatText::RequestLine,
+                        "s" => FormatText::ResponseStatus,
+                        "b" => FormatText::ResponseSize,
+                        "T" => FormatText::Time,
+                        "D" => FormatText::TimeMillis,
+                        _ => FormatText::Str(m.as_str().to_owned()),
+                    }
+                );
             }
         }
+        if idx != s.len() {
+            results.push(FormatText::Str(s[idx..].to_owned()));
+        }
 
-        Some(Format(results))
+        Format(results)
     }
 }
 
@@ -151,117 +245,25 @@ impl<'a> ContextDisplay<'a> for Format {
     }
 }
 
-struct FormatParser<'a> {
-    // The characters of the format string.
-    chars: Peekable<Chars<'a>>,
-
-    // A reusable buffer for parsing style attributes.
-    object_buffer: String,
-
-    finished: bool
-}
-
-impl<'a> FormatParser<'a> {
-    fn new(chars: Peekable<Chars>) -> FormatParser {
-        FormatParser {
-            chars: chars,
-
-            // No attributes are longer than 14 characters, so we can avoid reallocating.
-            object_buffer: String::with_capacity(14),
-
-            finished: false
-        }
-    }
-}
-
-// Some(None) means there was a parse error and this FormatParser should be abandoned.
-impl<'a> Iterator for FormatParser<'a> {
-    type Item = Option<FormatText>;
-
-    fn next(&mut self) -> Option<Option<FormatText>> {
-        // If the parser has been cancelled or errored for some reason.
-        if self.finished { return None }
-
-        // Try to parse a new FormatText.
-        match self.chars.next() {
-            // Parse a recognized object.
-            //
-            // The allowed forms are:
-            //   - {method}
-            //   - {uri}
-            //   - {status}
-            //   - {response-time}
-            //   - {ip-addr}
-            //   - {request-time}
-            Some('{') => {
-                self.object_buffer.clear();
-
-                let mut chr = self.chars.next();
-                while chr != None {
-                    match chr.unwrap() {
-                        // Finished parsing, parse buffer.
-                        '}' => break,
-                        c => self.object_buffer.push(c)
-                    }
-
-                    chr = self.chars.next();
-                }
-
-                let text = match self.object_buffer.as_ref() {
-                    "method" => Method,
-                    "uri" => URI,
-                    "status" => Status,
-                    "response-time" => ResponseTime,
-                    "request-time" => RequestTime,
-                    "ip-addr" => RemoteAddr,
-                    _ => {
-                        // Error, so mark as finished.
-                        self.finished = true;
-                        return Some(None);
-                    }
-                };
-
-                Some(Some(text))
-            }
-
-            // Parse a regular string part of the format string.
-            Some(c) => {
-                let mut buffer = String::new();
-                buffer.push(c);
-
-                loop {
-                    match self.chars.peek() {
-                        // Done parsing.
-                        Some(&'{') | None => return Some(Some(FormatText::Str(buffer))),
-
-                        Some(_) => {
-                            buffer.push(self.chars.next().unwrap())
-                        }
-                    }
-                }
-            },
-
-            // Reached end of the format string.
-            None => None
-        }
-    }
-}
-
 /// A string of text to be logged. This is either one of the data
 /// fields supported by the `Logger`, or a custom `String`.
-#[derive(Clone)]
 #[doc(hidden)]
+#[derive(Debug, Clone)]
 pub enum FormatText {
     Str(String),
-    Method,
+    Percent,
-    URI,
+    RequestLine,
-    Status,
+    RequestTime,
-    ResponseTime,
+    ResponseStatus,
+    ResponseSize,
+    Time,
+    TimeMillis,
     RemoteAddr,
-    RequestTime
+    RequestHeader(String),
+    ResponseHeader(String),
+    EnvironHeader(String),
 }
 
-
 pub(crate) struct FormatDisplay<'a> {
     format: &'a Format,
     render: &'a Fn(&mut Formatter, &FormatText) -> Result<(), fmt::Error>,

src/task.rs

@@ -277,7 +277,8 @@ impl Task {
         // response is completed
         if self.iostate.is_done() {
             // finish middlewares
-            if let Some(ref resp) = self.prepared {
+            if let Some(ref mut resp) = self.prepared {
+                resp.set_response_size(io.written());
                 match self.middlewares.finishing(req, resp) {
                     Ok(Async::NotReady) => return Ok(Async::NotReady),
                     _ => (),