2017-10-22 05:59:09 +00:00
|
|
|
//! Request logging middleware
|
2018-05-08 23:30:34 +00:00
|
|
|
use std::collections::HashSet;
|
2017-11-10 20:29:54 +00:00
|
|
|
use std::env;
|
2018-05-08 23:30:34 +00:00
|
|
|
use std::fmt::{self, Display, Formatter};
|
2017-10-22 05:59:09 +00:00
|
|
|
|
2017-11-10 20:29:54 +00:00
|
|
|
use regex::Regex;
|
2018-04-13 23:02:01 +00:00
|
|
|
use time;
|
2017-10-22 05:59:09 +00:00
|
|
|
|
2018-01-10 06:48:35 +00:00
|
|
|
use error::Result;
|
2018-02-27 23:03:28 +00:00
|
|
|
use httpmessage::HttpMessage;
|
2017-10-22 05:59:09 +00:00
|
|
|
use httprequest::HttpRequest;
|
|
|
|
use httpresponse::HttpResponse;
|
2018-04-13 23:02:01 +00:00
|
|
|
use middleware::{Finished, Middleware, Started};
|
2017-10-22 05:59:09 +00:00
|
|
|
|
|
|
|
/// `Middleware` for logging request and response info to the terminal.
|
2018-04-19 03:41:03 +00:00
|
|
|
///
|
2018-02-20 20:53:51 +00:00
|
|
|
/// `Logger` middleware uses standard log crate to log information. You should
|
2018-02-21 22:31:22 +00:00
|
|
|
/// enable logger for `actix_web` package to see access log.
|
|
|
|
/// ([`env_logger`](https://docs.rs/env_logger/*/env_logger/) or similar)
|
2017-11-10 20:29:54 +00:00
|
|
|
///
|
|
|
|
/// ## Usage
|
|
|
|
///
|
2017-12-27 03:59:41 +00:00
|
|
|
/// Create `Logger` middleware with the specified `format`.
|
2018-04-13 23:02:01 +00:00
|
|
|
/// Default `Logger` could be created with `default` method, it uses the
|
|
|
|
/// default format:
|
2017-11-10 20:29:54 +00:00
|
|
|
///
|
|
|
|
/// ```ignore
|
2018-01-01 01:26:32 +00:00
|
|
|
/// %a %t "%r" %s %b "%{Referer}i" "%{User-Agent}i" %T
|
2017-11-10 20:29:54 +00:00
|
|
|
/// ```
|
2017-11-23 23:17:16 +00:00
|
|
|
/// ```rust
|
2017-12-06 19:00:39 +00:00
|
|
|
/// # extern crate actix_web;
|
2018-02-20 20:53:51 +00:00
|
|
|
/// extern crate env_logger;
|
2017-12-27 03:59:41 +00:00
|
|
|
/// use actix_web::middleware::Logger;
|
2018-06-01 16:37:14 +00:00
|
|
|
/// use actix_web::App;
|
2017-11-10 20:29:54 +00:00
|
|
|
///
|
2017-11-23 23:17:16 +00:00
|
|
|
/// fn main() {
|
2018-02-20 20:53:51 +00:00
|
|
|
/// std::env::set_var("RUST_LOG", "actix_web=info");
|
|
|
|
/// env_logger::init();
|
|
|
|
///
|
2018-03-31 07:16:55 +00:00
|
|
|
/// let app = App::new()
|
2017-11-23 23:17:16 +00:00
|
|
|
/// .middleware(Logger::default())
|
|
|
|
/// .middleware(Logger::new("%a %{User-Agent}i"))
|
|
|
|
/// .finish();
|
|
|
|
/// }
|
2017-11-10 20:29:54 +00:00
|
|
|
/// ```
|
|
|
|
///
|
|
|
|
/// ## 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
|
|
|
|
///
|
|
|
|
/// `%r` First line of request
|
|
|
|
///
|
|
|
|
/// `%s` Response status code
|
|
|
|
///
|
|
|
|
/// `%b` Size of response in bytes, including HTTP headers
|
|
|
|
///
|
2018-04-13 23:02:01 +00:00
|
|
|
/// `%T` Time taken to serve the request, in seconds with floating fraction in
|
|
|
|
/// .06f format
|
2017-11-10 20:29:54 +00:00
|
|
|
///
|
|
|
|
/// `%D` Time taken to serve the request, in milliseconds
|
|
|
|
///
|
|
|
|
/// `%{FOO}i` request.headers['FOO']
|
|
|
|
///
|
|
|
|
/// `%{FOO}o` response.headers['FOO']
|
|
|
|
///
|
|
|
|
/// `%{FOO}e` os.environ['FOO']
|
|
|
|
///
|
2017-10-22 05:59:09 +00:00
|
|
|
pub struct Logger {
|
|
|
|
format: Format,
|
2018-05-08 23:30:34 +00:00
|
|
|
exclude: HashSet<String>,
|
2017-10-22 05:59:09 +00:00
|
|
|
}
|
|
|
|
|
|
|
|
impl Logger {
|
2017-11-10 20:29:54 +00:00
|
|
|
/// Create `Logger` middleware with the specified `format`.
|
|
|
|
pub fn new(format: &str) -> Logger {
|
2018-04-13 23:02:01 +00:00
|
|
|
Logger {
|
|
|
|
format: Format::new(format),
|
2018-05-08 23:30:34 +00:00
|
|
|
exclude: HashSet::new(),
|
2018-04-13 23:02:01 +00:00
|
|
|
}
|
2017-11-10 20:29:54 +00:00
|
|
|
}
|
2018-05-08 23:30:34 +00:00
|
|
|
|
|
|
|
/// Ignore and do not log access info for specified path.
|
|
|
|
pub fn exclude<T: Into<String>>(mut self, path: T) -> Self {
|
|
|
|
self.exclude.insert(path.into());
|
|
|
|
self
|
|
|
|
}
|
2017-11-10 20:29:54 +00:00
|
|
|
}
|
|
|
|
|
|
|
|
impl Default for Logger {
|
2017-11-10 21:34:16 +00:00
|
|
|
/// Create `Logger` middleware with format:
|
|
|
|
///
|
|
|
|
/// ```ignore
|
2018-01-01 01:26:32 +00:00
|
|
|
/// %a %t "%r" %s %b "%{Referer}i" "%{User-Agent}i" %T
|
2017-11-10 21:34:16 +00:00
|
|
|
/// ```
|
2017-11-10 20:29:54 +00:00
|
|
|
fn default() -> Logger {
|
2018-04-13 23:02:01 +00:00
|
|
|
Logger {
|
|
|
|
format: Format::default(),
|
2018-05-08 23:30:34 +00:00
|
|
|
exclude: HashSet::new(),
|
2018-04-13 23:02:01 +00:00
|
|
|
}
|
2017-10-22 05:59:09 +00:00
|
|
|
}
|
|
|
|
}
|
|
|
|
|
|
|
|
struct StartTime(time::Tm);
|
|
|
|
|
|
|
|
impl Logger {
|
2018-06-25 04:58:04 +00:00
|
|
|
fn log<S>(&self, req: &HttpRequest<S>, resp: &HttpResponse) {
|
2018-05-08 23:30:34 +00:00
|
|
|
if let Some(entry_time) = req.extensions().get::<StartTime>() {
|
|
|
|
let render = |fmt: &mut Formatter| {
|
|
|
|
for unit in &self.format.0 {
|
|
|
|
unit.render(fmt, req, resp, entry_time.0)?;
|
|
|
|
}
|
|
|
|
Ok(())
|
|
|
|
};
|
|
|
|
info!("{}", FormatDisplay(&render));
|
|
|
|
}
|
2017-10-22 05:59:09 +00:00
|
|
|
}
|
|
|
|
}
|
|
|
|
|
2017-12-09 12:33:40 +00:00
|
|
|
impl<S> Middleware<S> for Logger {
|
2018-06-25 04:58:04 +00:00
|
|
|
fn start(&self, req: &HttpRequest<S>) -> Result<Started> {
|
2018-05-08 23:30:34 +00:00
|
|
|
if !self.exclude.contains(req.path()) {
|
|
|
|
req.extensions_mut().insert(StartTime(time::now()));
|
|
|
|
}
|
2018-01-10 06:48:35 +00:00
|
|
|
Ok(Started::Done)
|
2017-10-22 05:59:09 +00:00
|
|
|
}
|
|
|
|
|
2018-06-25 04:58:04 +00:00
|
|
|
fn finish(&self, req: &HttpRequest<S>, resp: &HttpResponse) -> Finished {
|
2017-10-22 05:59:09 +00:00
|
|
|
self.log(req, resp);
|
2017-11-10 06:08:54 +00:00
|
|
|
Finished::Done
|
2017-10-22 05:59:09 +00:00
|
|
|
}
|
|
|
|
}
|
|
|
|
|
|
|
|
/// A formatting style for the `Logger`, consisting of multiple
|
|
|
|
/// `FormatText`s concatenated into one line.
|
|
|
|
#[derive(Clone)]
|
|
|
|
#[doc(hidden)]
|
2017-11-10 20:29:54 +00:00
|
|
|
struct Format(Vec<FormatText>);
|
2017-10-22 05:59:09 +00:00
|
|
|
|
|
|
|
impl Default for Format {
|
|
|
|
/// Return the default formatting style for the `Logger`:
|
|
|
|
fn default() -> Format {
|
2018-01-01 01:26:32 +00:00
|
|
|
Format::new(r#"%a %t "%r" %s %b "%{Referer}i" "%{User-Agent}i" %T"#)
|
2017-10-22 05:59:09 +00:00
|
|
|
}
|
|
|
|
}
|
|
|
|
|
|
|
|
impl Format {
|
2017-11-10 20:29:54 +00:00
|
|
|
/// Create a `Format` from a format string.
|
2017-10-22 05:59:09 +00:00
|
|
|
///
|
|
|
|
/// Returns `None` if the format string syntax is incorrect.
|
2017-11-10 20:29:54 +00:00
|
|
|
pub fn new(s: &str) -> Format {
|
|
|
|
trace!("Access log format: {}", s);
|
|
|
|
let fmt = Regex::new(r"%(\{([A-Za-z0-9\-_]+)\}([ioe])|[atPrsbTD]?)").unwrap();
|
2017-10-22 05:59:09 +00:00
|
|
|
|
2017-11-10 20:29:54 +00:00
|
|
|
let mut idx = 0;
|
2017-10-22 05:59:09 +00:00
|
|
|
let mut results = Vec::new();
|
2017-11-10 20:29:54 +00:00
|
|
|
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()));
|
2017-10-22 05:59:09 +00:00
|
|
|
}
|
2017-11-10 20:29:54 +00:00
|
|
|
idx = m.end();
|
|
|
|
|
|
|
|
if let Some(key) = cap.get(2) {
|
2018-04-13 23:02:01 +00:00
|
|
|
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!(),
|
|
|
|
})
|
2017-11-10 20:29:54 +00:00
|
|
|
} else {
|
|
|
|
let m = cap.get(1).unwrap();
|
2018-04-13 23:02:01 +00:00
|
|
|
results.push(match m.as_str() {
|
|
|
|
"%" => FormatText::Percent,
|
|
|
|
"a" => FormatText::RemoteAddr,
|
|
|
|
"t" => FormatText::RequestTime,
|
|
|
|
"r" => FormatText::RequestLine,
|
|
|
|
"s" => FormatText::ResponseStatus,
|
|
|
|
"b" => FormatText::ResponseSize,
|
|
|
|
"T" => FormatText::Time,
|
|
|
|
"D" => FormatText::TimeMillis,
|
|
|
|
_ => FormatText::Str(m.as_str().to_owned()),
|
|
|
|
});
|
2017-11-10 20:29:54 +00:00
|
|
|
}
|
|
|
|
}
|
|
|
|
if idx != s.len() {
|
|
|
|
results.push(FormatText::Str(s[idx..].to_owned()));
|
2017-10-22 05:59:09 +00:00
|
|
|
}
|
|
|
|
|
2017-11-10 20:29:54 +00:00
|
|
|
Format(results)
|
2017-10-22 05:59:09 +00:00
|
|
|
}
|
|
|
|
}
|
|
|
|
|
|
|
|
/// A string of text to be logged. This is either one of the data
|
|
|
|
/// fields supported by the `Logger`, or a custom `String`.
|
|
|
|
#[doc(hidden)]
|
2017-11-10 20:29:54 +00:00
|
|
|
#[derive(Debug, Clone)]
|
2017-10-22 05:59:09 +00:00
|
|
|
pub enum FormatText {
|
|
|
|
Str(String),
|
2017-11-10 20:29:54 +00:00
|
|
|
Percent,
|
|
|
|
RequestLine,
|
|
|
|
RequestTime,
|
|
|
|
ResponseStatus,
|
|
|
|
ResponseSize,
|
|
|
|
Time,
|
|
|
|
TimeMillis,
|
2017-10-22 05:59:09 +00:00
|
|
|
RemoteAddr,
|
2017-11-10 20:29:54 +00:00
|
|
|
RequestHeader(String),
|
|
|
|
ResponseHeader(String),
|
|
|
|
EnvironHeader(String),
|
2017-10-22 05:59:09 +00:00
|
|
|
}
|
|
|
|
|
2017-11-23 23:17:16 +00:00
|
|
|
impl FormatText {
|
2018-04-13 23:02:01 +00:00
|
|
|
fn render<S>(
|
|
|
|
&self, fmt: &mut Formatter, req: &HttpRequest<S>, resp: &HttpResponse,
|
|
|
|
entry_time: time::Tm,
|
|
|
|
) -> Result<(), fmt::Error> {
|
2017-11-23 23:17:16 +00:00
|
|
|
match *self {
|
|
|
|
FormatText::Str(ref string) => fmt.write_str(string),
|
|
|
|
FormatText::Percent => "%".fmt(fmt),
|
|
|
|
FormatText::RequestLine => {
|
|
|
|
if req.query_string().is_empty() {
|
|
|
|
fmt.write_fmt(format_args!(
|
|
|
|
"{} {} {:?}",
|
2018-04-13 23:02:01 +00:00
|
|
|
req.method(),
|
|
|
|
req.path(),
|
|
|
|
req.version()
|
|
|
|
))
|
2017-11-23 23:17:16 +00:00
|
|
|
} else {
|
|
|
|
fmt.write_fmt(format_args!(
|
|
|
|
"{} {}?{} {:?}",
|
2018-04-13 23:02:01 +00:00
|
|
|
req.method(),
|
|
|
|
req.path(),
|
|
|
|
req.query_string(),
|
|
|
|
req.version()
|
|
|
|
))
|
2017-11-23 23:17:16 +00:00
|
|
|
}
|
2018-04-13 23:02:01 +00:00
|
|
|
}
|
2017-11-23 23:17:16 +00:00
|
|
|
FormatText::ResponseStatus => resp.status().as_u16().fmt(fmt),
|
|
|
|
FormatText::ResponseSize => resp.response_size().fmt(fmt),
|
|
|
|
FormatText::Time => {
|
2018-04-02 18:09:24 +00:00
|
|
|
let rt = time::now() - entry_time;
|
|
|
|
let rt = (rt.num_nanoseconds().unwrap_or(0) as f64) / 1_000_000_000.0;
|
|
|
|
fmt.write_fmt(format_args!("{:.6}", rt))
|
2018-04-13 23:02:01 +00:00
|
|
|
}
|
2017-11-23 23:17:16 +00:00
|
|
|
FormatText::TimeMillis => {
|
2018-04-02 18:09:24 +00:00
|
|
|
let rt = time::now() - entry_time;
|
|
|
|
let rt = (rt.num_nanoseconds().unwrap_or(0) as f64) / 1_000_000.0;
|
|
|
|
fmt.write_fmt(format_args!("{:.6}", rt))
|
2018-04-13 23:02:01 +00:00
|
|
|
}
|
2017-11-23 23:17:16 +00:00
|
|
|
FormatText::RemoteAddr => {
|
2017-12-08 01:38:18 +00:00
|
|
|
if let Some(remote) = req.connection_info().remote() {
|
|
|
|
return remote.fmt(fmt);
|
|
|
|
} else {
|
|
|
|
"-".fmt(fmt)
|
2017-11-23 23:17:16 +00:00
|
|
|
}
|
|
|
|
}
|
2018-04-29 16:09:08 +00:00
|
|
|
FormatText::RequestTime => entry_time
|
|
|
|
.strftime("[%d/%b/%Y:%H:%M:%S %z]")
|
|
|
|
.unwrap()
|
|
|
|
.fmt(fmt),
|
2017-11-23 23:17:16 +00:00
|
|
|
FormatText::RequestHeader(ref name) => {
|
|
|
|
let s = if let Some(val) = req.headers().get(name) {
|
2018-04-13 23:02:01 +00:00
|
|
|
if let Ok(s) = val.to_str() {
|
|
|
|
s
|
|
|
|
} else {
|
|
|
|
"-"
|
|
|
|
}
|
2017-11-23 23:17:16 +00:00
|
|
|
} else {
|
|
|
|
"-"
|
|
|
|
};
|
|
|
|
fmt.write_fmt(format_args!("{}", s))
|
|
|
|
}
|
|
|
|
FormatText::ResponseHeader(ref name) => {
|
|
|
|
let s = if let Some(val) = resp.headers().get(name) {
|
2018-04-13 23:02:01 +00:00
|
|
|
if let Ok(s) = val.to_str() {
|
|
|
|
s
|
|
|
|
} else {
|
|
|
|
"-"
|
|
|
|
}
|
2017-11-23 23:17:16 +00:00
|
|
|
} 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)
|
|
|
|
}
|
|
|
|
}
|
|
|
|
}
|
|
|
|
}
|
2017-10-22 05:59:09 +00:00
|
|
|
}
|
|
|
|
|
2018-04-13 23:02:01 +00:00
|
|
|
pub(crate) struct FormatDisplay<'a>(&'a Fn(&mut Formatter) -> Result<(), fmt::Error>);
|
2017-11-23 23:17:16 +00:00
|
|
|
|
2017-10-22 05:59:09 +00:00
|
|
|
impl<'a> fmt::Display for FormatDisplay<'a> {
|
|
|
|
fn fmt(&self, fmt: &mut Formatter) -> Result<(), fmt::Error> {
|
2017-11-23 23:17:16 +00:00
|
|
|
(self.0)(fmt)
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
|
|
|
#[cfg(test)]
|
|
|
|
mod tests {
|
2018-07-04 15:01:27 +00:00
|
|
|
use time;
|
|
|
|
|
2017-11-23 23:17:16 +00:00
|
|
|
use super::*;
|
2018-07-04 15:01:27 +00:00
|
|
|
use http::{header, StatusCode};
|
2018-06-25 04:58:04 +00:00
|
|
|
use test::TestRequest;
|
2017-11-23 23:17:16 +00:00
|
|
|
|
|
|
|
#[test]
|
2017-11-23 23:37:11 +00:00
|
|
|
fn test_logger() {
|
2018-06-21 17:06:23 +00:00
|
|
|
let logger = Logger::new("%% %{User-Agent}i %{X-Test}o %{HOME}e %D test");
|
2017-11-23 23:37:11 +00:00
|
|
|
|
2018-06-25 04:58:04 +00:00
|
|
|
let req = TestRequest::with_header(
|
2018-04-29 16:09:08 +00:00
|
|
|
header::USER_AGENT,
|
|
|
|
header::HeaderValue::from_static("ACTIX-WEB"),
|
2018-06-25 04:58:04 +00:00
|
|
|
).finish();
|
2017-11-27 06:31:29 +00:00
|
|
|
let resp = HttpResponse::build(StatusCode::OK)
|
2017-11-23 23:37:11 +00:00
|
|
|
.header("X-Test", "ttt")
|
2018-03-31 06:07:33 +00:00
|
|
|
.force_close()
|
|
|
|
.finish();
|
2017-11-23 23:37:11 +00:00
|
|
|
|
2018-06-25 04:58:04 +00:00
|
|
|
match logger.start(&req) {
|
2018-01-10 06:48:35 +00:00
|
|
|
Ok(Started::Done) => (),
|
2017-11-23 23:37:11 +00:00
|
|
|
_ => panic!(),
|
2017-11-25 06:15:52 +00:00
|
|
|
};
|
2018-06-25 04:58:04 +00:00
|
|
|
match logger.finish(&req, &resp) {
|
2017-11-23 23:37:11 +00:00
|
|
|
Finished::Done => (),
|
|
|
|
_ => panic!(),
|
|
|
|
}
|
2017-11-24 00:53:02 +00:00
|
|
|
let entry_time = time::now();
|
|
|
|
let render = |fmt: &mut Formatter| {
|
2018-04-05 03:24:09 +00:00
|
|
|
for unit in &logger.format.0 {
|
2017-11-24 00:53:02 +00:00
|
|
|
unit.render(fmt, &req, &resp, entry_time)?;
|
|
|
|
}
|
|
|
|
Ok(())
|
|
|
|
};
|
|
|
|
let s = format!("{}", FormatDisplay(&render));
|
|
|
|
assert!(s.contains("ACTIX-WEB ttt"));
|
2017-11-23 23:37:11 +00:00
|
|
|
}
|
|
|
|
|
|
|
|
#[test]
|
|
|
|
fn test_default_format() {
|
2017-11-23 23:17:16 +00:00
|
|
|
let format = Format::default();
|
|
|
|
|
2018-06-25 04:58:04 +00:00
|
|
|
let req = TestRequest::with_header(
|
2018-04-29 16:09:08 +00:00
|
|
|
header::USER_AGENT,
|
|
|
|
header::HeaderValue::from_static("ACTIX-WEB"),
|
2018-06-25 04:58:04 +00:00
|
|
|
).finish();
|
2018-05-17 19:20:20 +00:00
|
|
|
let resp = HttpResponse::build(StatusCode::OK).force_close().finish();
|
2017-11-23 23:17:16 +00:00
|
|
|
let entry_time = time::now();
|
|
|
|
|
|
|
|
let render = |fmt: &mut Formatter| {
|
2018-04-05 03:24:09 +00:00
|
|
|
for unit in &format.0 {
|
2017-11-23 23:17:16 +00:00
|
|
|
unit.render(fmt, &req, &resp, entry_time)?;
|
|
|
|
}
|
|
|
|
Ok(())
|
|
|
|
};
|
|
|
|
let s = format!("{}", FormatDisplay(&render));
|
|
|
|
assert!(s.contains("GET / HTTP/1.1"));
|
|
|
|
assert!(s.contains("200 0"));
|
|
|
|
assert!(s.contains("ACTIX-WEB"));
|
|
|
|
|
2018-06-25 04:58:04 +00:00
|
|
|
let req = TestRequest::with_uri("/?test").finish();
|
2018-05-17 19:20:20 +00:00
|
|
|
let resp = HttpResponse::build(StatusCode::OK).force_close().finish();
|
2017-11-23 23:17:16 +00:00
|
|
|
let entry_time = time::now();
|
|
|
|
|
|
|
|
let render = |fmt: &mut Formatter| {
|
2018-04-05 03:24:09 +00:00
|
|
|
for unit in &format.0 {
|
2017-11-23 23:17:16 +00:00
|
|
|
unit.render(fmt, &req, &resp, entry_time)?;
|
|
|
|
}
|
|
|
|
Ok(())
|
|
|
|
};
|
|
|
|
let s = format!("{}", FormatDisplay(&render));
|
|
|
|
assert!(s.contains("GET /?test HTTP/1.1"));
|
2017-10-22 05:59:09 +00:00
|
|
|
}
|
|
|
|
}
|