diff --git a/README.md b/README.md index aa94f00f..26d145d6 100644 --- a/README.md +++ b/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::()) .route_handler("/", StaticFiles::new("examples/static/", true))) diff --git a/examples/basic.rs b/examples/basic.rs index 19eee567..7e05b07c 100644 --- a/examples/basic.rs +++ b/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 diff --git a/examples/state.rs b/examples/state.rs index 27b45696..3b7bba38 100644 --- a/examples/state.rs +++ b/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::()) // register simple handler, handle all methods diff --git a/examples/tls/src/main.rs b/examples/tls/src/main.rs index 742a9f69..90fd11b1 100644 --- a/examples/tls/src/main.rs +++ b/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 diff --git a/examples/websocket.rs b/examples/websocket.rs index a70ac71a..634c4f18 100644 --- a/examples/websocket.rs +++ b/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::()) .route_handler("/", StaticFiles::new("examples/static/", true))) diff --git a/src/h1.rs b/src/h1.rs index 16d25058..97f9aa08 100644 --- a/src/h1.rs +++ b/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(); diff --git a/src/h1writer.rs b/src/h1writer.rs index 838229a0..63c98e87 100644 --- a/src/h1writer.rs +++ b/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; @@ -41,6 +43,8 @@ pub(crate) struct H1Writer { upgrade: bool, keepalive: bool, disconnected: bool, + written: u64, + headers_size: u64, } impl H1Writer { @@ -53,6 +57,8 @@ impl H1Writer { upgrade: false, keepalive: false, disconnected: false, + written: 0, + headers_size: 0, } } @@ -80,6 +86,7 @@ impl H1Writer { 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 H1Writer { impl Writer for H1Writer { + 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 { @@ -162,6 +177,7 @@ impl Writer for H1Writer { // msg eof buffer.extend(b"\r\n"); + self.headers_size = buffer.len() as u64; } trace!("Response: {:?}", msg); diff --git a/src/h2writer.rs b/src/h2writer.rs index 88f1830c..e3e04bd7 100644 --- a/src/h2writer.rs +++ b/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 { diff --git a/src/httpresponse.rs b/src/httpresponse.rs index 72a909ef..7d5bcee6 100644 --- a/src/httpresponse.rs +++ b/src/httpresponse.rs @@ -34,6 +34,7 @@ pub struct HttpResponse { encoding: ContentEncoding, connection_type: Option, error: Option>, + 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>(&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, }) } diff --git a/src/middlewares/logger.rs b/src/middlewares/logger.rs index 52c43e34..f0d11c89 100644 --- a/src/middlewares/logger.rs +++ b/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`. - /// If a `None` is passed in, uses the default format: - /// - /// ```ignore - /// {method} {uri} -> {status} ({response-time} ms) - /// ``` - /// - /// ```rust,ignore - /// let app = Application::default("/") - /// .middleware(Logger::new(None)) - /// .finish() - /// ``` - pub fn new(format: Option) -> Logger { - let format = format.unwrap_or_default(); - Logger { format: format.clone() } + /// Create `Logger` middleware with the specified `format`. + pub fn new(format: &str) -> Logger { + Logger { format: Format::new(format) } + } +} + +impl Default for Logger { + /// Create default `Logger` middleware + fn default() -> Logger { + Logger { format: Format::default() } } } @@ -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::URI => { + FormatText::Percent => "%".fmt(fmt), + 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::ResponseTime => - fmt.write_fmt(format_args!("{} sec", response_time_ms)), + FormatText::ResponseStatus => resp.status().as_u16().fmt(fmt), + FormatText::ResponseSize => resp.response_size().fmt(fmt), + 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); +struct Format(Vec); impl Default for Format { /// Return the default formatting style for the `Logger`: /// /// ```ignore - /// {method} {uri} -> {status} ({response-time}) - /// // This will be written as: {method} {uri} -> {status} ({response-time}) + /// %a %t "%r" %s %b "%{Referrer}i" "%{User-Agent}i %T" /// ``` 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 - /// `{method}`, `{uri}`, `{status}`, `{response-time}`, `{ip-addr}` and - /// `{request-time}`. + /// Create a `Format` from a format string. /// /// Returns `None` if the format string syntax is incorrect. - pub fn new(s: &str) -> Option { - - let parser = FormatParser::new(s.chars().peekable()); + pub fn new(s: &str) -> Format { + trace!("Access log format: {}", s); + 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 { - match unit { - Some(unit) => results.push(unit), - None => return None + if let Some(key) = cap.get(2) { + results.push( + match cap.get(3).unwrap().as_str() { + "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>, - - // A reusable buffer for parsing style attributes. - object_buffer: String, - - finished: bool -} - -impl<'a> FormatParser<'a> { - fn new(chars: Peekable) -> 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; - - fn next(&mut self) -> Option> { - // 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, - URI, - Status, - ResponseTime, + Percent, + RequestLine, + RequestTime, + 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>, diff --git a/src/task.rs b/src/task.rs index ce1447c7..494d2236 100644 --- a/src/task.rs +++ b/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), _ => (),