actix_web/middleware/
logger.rs

1//! For middleware documentation, see [`Logger`].
2
3use std::{
4    borrow::Cow,
5    collections::HashSet,
6    env,
7    fmt::{self, Display as _},
8    future::Future,
9    marker::PhantomData,
10    pin::Pin,
11    rc::Rc,
12    task::{Context, Poll},
13};
14
15use actix_service::{Service, Transform};
16use actix_utils::future::{ready, Ready};
17use bytes::Bytes;
18use futures_core::ready;
19use log::{debug, warn, Level};
20use pin_project_lite::pin_project;
21#[cfg(feature = "unicode")]
22use regex::Regex;
23#[cfg(not(feature = "unicode"))]
24use regex_lite::Regex;
25use time::{format_description::well_known::Rfc3339, OffsetDateTime};
26
27use crate::{
28    body::{BodySize, MessageBody},
29    http::header::HeaderName,
30    service::{ServiceRequest, ServiceResponse},
31    Error, Result,
32};
33
34/// Middleware for logging request and response summaries to the terminal.
35///
36/// This middleware uses the `log` crate to output information. Enable `log`'s output for the
37/// "actix_web" scope using [`env_logger`](https://docs.rs/env_logger) or similar crate.
38///
39/// # Default Format
40/// The [`default`](Logger::default) Logger uses the following format:
41///
42/// ```plain
43/// %a "%r" %s %b "%{Referer}i" "%{User-Agent}i" %T
44///
45/// Example Output:
46/// 127.0.0.1:54278 "GET /test HTTP/1.1" 404 20 "-" "HTTPie/2.2.0" 0.001074
47/// ```
48///
49/// # Examples
50/// ```
51/// use actix_web::{middleware::Logger, App};
52///
53/// // access logs are printed with the INFO level so ensure it is enabled by default
54/// env_logger::init_from_env(env_logger::Env::new().default_filter_or("info"));
55///
56/// let app = App::new()
57///     // .wrap(Logger::default())
58///     .wrap(Logger::new("%a %{User-Agent}i"));
59/// ```
60///
61/// # Format
62/// Variable | Description
63/// -------- | -----------
64/// `%%` | The percent sign
65/// `%a` | Peer IP address (or IP address of reverse proxy if used)
66/// `%t` | Time when the request started processing (in RFC 3339 format)
67/// `%r` | First line of request (Example: `GET /test HTTP/1.1`)
68/// `%s` | Response status code
69/// `%b` | Size of response in bytes, including HTTP headers
70/// `%T` | Time taken to serve the request, in seconds to 6 decimal places
71/// `%D` | Time taken to serve the request, in milliseconds
72/// `%U` | Request URL
73/// `%{r}a` | "Real IP" remote address **\***
74/// `%{FOO}i` | `request.headers["FOO"]`
75/// `%{FOO}o` | `response.headers["FOO"]`
76/// `%{FOO}e` | `env_var["FOO"]`
77/// `%{FOO}xi` | [Custom request replacement](Logger::custom_request_replace) labelled "FOO"
78/// `%{FOO}xo` | [Custom response replacement](Logger::custom_response_replace) labelled "FOO"
79///
80/// # Security
81/// **\*** "Real IP" remote address is calculated using
82/// [`ConnectionInfo::realip_remote_addr()`](crate::dev::ConnectionInfo::realip_remote_addr())
83///
84/// If you use this value, ensure that all requests come from trusted hosts. Otherwise, it is
85/// trivial for the remote client to falsify their source IP address.
86#[derive(Debug)]
87pub struct Logger(Rc<Inner>);
88
89#[derive(Debug, Clone)]
90struct Inner {
91    format: Format,
92    exclude: HashSet<String>,
93    exclude_regex: Vec<Regex>,
94    log_target: Cow<'static, str>,
95    log_level: Level,
96}
97
98impl Logger {
99    /// Create `Logger` middleware with the specified `format`.
100    pub fn new(format: &str) -> Logger {
101        Logger(Rc::new(Inner {
102            format: Format::new(format),
103            exclude: HashSet::new(),
104            exclude_regex: Vec::new(),
105            log_target: Cow::Borrowed(module_path!()),
106            log_level: Level::Info,
107        }))
108    }
109
110    /// Ignore and do not log access info for specified path.
111    pub fn exclude<T: Into<String>>(mut self, path: T) -> Self {
112        Rc::get_mut(&mut self.0)
113            .unwrap()
114            .exclude
115            .insert(path.into());
116        self
117    }
118
119    /// Ignore and do not log access info for paths that match regex.
120    pub fn exclude_regex<T: Into<String>>(mut self, path: T) -> Self {
121        let inner = Rc::get_mut(&mut self.0).unwrap();
122        inner.exclude_regex.push(Regex::new(&path.into()).unwrap());
123        self
124    }
125
126    /// Sets the logging target to `target`.
127    ///
128    /// By default, the log target is `module_path!()` of the log call location. In our case, that
129    /// would be `actix_web::middleware::logger`.
130    ///
131    /// # Examples
132    /// Using `.log_target("http_log")` would have this effect on request logs:
133    /// ```diff
134    /// - [2015-10-21T07:28:00Z INFO  actix_web::middleware::logger] 127.0.0.1 "GET / HTTP/1.1" 200 88 "-" "dmc/1.0" 0.001985
135    /// + [2015-10-21T07:28:00Z INFO  http_log] 127.0.0.1 "GET / HTTP/1.1" 200 88 "-" "dmc/1.0" 0.001985
136    ///                               ^^^^^^^^
137    /// ```
138    pub fn log_target(mut self, target: impl Into<Cow<'static, str>>) -> Self {
139        let inner = Rc::get_mut(&mut self.0).unwrap();
140        inner.log_target = target.into();
141        self
142    }
143
144    /// Sets the log level to `level`.
145    ///
146    /// By default, the log level is `Level::Info`.
147    ///
148    /// # Examples
149    /// Using `.log_level(Level::Debug)` would have this effect on request logs:
150    /// ```diff
151    /// - [2015-10-21T07:28:00Z INFO  actix_web::middleware::logger] 127.0.0.1 "GET / HTTP/1.1" 200 88 "-" "dmc/1.0" 0.001985
152    /// + [2015-10-21T07:28:00Z DEBUG  actix_web::middleware::logger] 127.0.0.1 "GET / HTTP/1.1" 200 88 "-" "dmc/1.0" 0.001985
153    ///                         ^^^^^^
154    /// ```
155    pub fn log_level(mut self, level: log::Level) -> Self {
156        let inner = Rc::get_mut(&mut self.0).unwrap();
157        inner.log_level = level;
158        self
159    }
160
161    /// Register a function that receives a ServiceRequest and returns a String for use in the
162    /// log line. The label passed as the first argument should match a replacement substring in
163    /// the logger format like `%{label}xi`.
164    ///
165    /// It is convention to print "-" to indicate no output instead of an empty string.
166    ///
167    /// # Examples
168    /// ```
169    /// # use actix_web::http::{header::HeaderValue};
170    /// # use actix_web::middleware::Logger;
171    /// # fn parse_jwt_id (_req: Option<&HeaderValue>) -> String { "jwt_uid".to_owned() }
172    /// Logger::new("example %{JWT_ID}xi")
173    ///     .custom_request_replace("JWT_ID", |req| parse_jwt_id(req.headers().get("Authorization")));
174    /// ```
175    pub fn custom_request_replace(
176        mut self,
177        label: &str,
178        f: impl Fn(&ServiceRequest) -> String + 'static,
179    ) -> Self {
180        let inner = Rc::get_mut(&mut self.0).unwrap();
181
182        let ft = inner.format.0.iter_mut().find(
183            |ft| matches!(ft, FormatText::CustomRequest(unit_label, _) if label == unit_label),
184        );
185
186        if let Some(FormatText::CustomRequest(_, request_fn)) = ft {
187            // replace into None or previously registered fn using same label
188            request_fn.replace(CustomRequestFn {
189                inner_fn: Rc::new(f),
190            });
191        } else {
192            // non-printed request replacement function diagnostic
193            debug!(
194                "Attempted to register custom request logging function for nonexistent label: {}",
195                label
196            );
197        }
198
199        self
200    }
201
202    /// Register a function that receives a `ServiceResponse` and returns a string for use in the
203    /// log line.
204    ///
205    /// The label passed as the first argument should match a replacement substring in
206    /// the logger format like `%{label}xo`.
207    ///
208    /// It is convention to print "-" to indicate no output instead of an empty string.
209    ///
210    /// The replacement function does not have access to the response body.
211    ///
212    /// # Examples
213    /// ```
214    /// # use actix_web::{dev::ServiceResponse, middleware::Logger};
215    /// fn log_if_error(res: &ServiceResponse) -> String {
216    ///     if res.status().as_u16() >= 400 {
217    ///         "ERROR".to_string()
218    ///     } else {
219    ///         "-".to_string()
220    ///     }
221    /// }
222    ///
223    /// Logger::new("example %{ERROR_STATUS}xo")
224    ///     .custom_response_replace("ERROR_STATUS", |res| log_if_error(res) );
225    /// ```
226    pub fn custom_response_replace(
227        mut self,
228        label: &str,
229        f: impl Fn(&ServiceResponse) -> String + 'static,
230    ) -> Self {
231        let inner = Rc::get_mut(&mut self.0).unwrap();
232
233        let ft = inner.format.0.iter_mut().find(
234            |ft| matches!(ft, FormatText::CustomResponse(unit_label, _) if label == unit_label),
235        );
236
237        if let Some(FormatText::CustomResponse(_, res_fn)) = ft {
238            *res_fn = Some(CustomResponseFn {
239                inner_fn: Rc::new(f),
240            });
241        } else {
242            debug!(
243                "Attempted to register custom response logging function for non-existent label: {}",
244                label
245            );
246        }
247
248        self
249    }
250}
251
252impl Default for Logger {
253    /// Create `Logger` middleware with format:
254    ///
255    /// ```plain
256    /// %a "%r" %s %b "%{Referer}i" "%{User-Agent}i" %T
257    /// ```
258    fn default() -> Logger {
259        Logger(Rc::new(Inner {
260            format: Format::default(),
261            exclude: HashSet::new(),
262            exclude_regex: Vec::new(),
263            log_target: Cow::Borrowed(module_path!()),
264            log_level: Level::Info,
265        }))
266    }
267}
268
269impl<S, B> Transform<S, ServiceRequest> for Logger
270where
271    S: Service<ServiceRequest, Response = ServiceResponse<B>, Error = Error>,
272    B: MessageBody,
273{
274    type Response = ServiceResponse<StreamLog<B>>;
275    type Error = Error;
276    type Transform = LoggerMiddleware<S>;
277    type InitError = ();
278    type Future = Ready<Result<Self::Transform, Self::InitError>>;
279
280    fn new_transform(&self, service: S) -> Self::Future {
281        for unit in &self.0.format.0 {
282            if let FormatText::CustomRequest(label, None) = unit {
283                warn!(
284                    "No custom request replacement function was registered for label: {}",
285                    label
286                );
287            }
288
289            if let FormatText::CustomResponse(label, None) = unit {
290                warn!(
291                    "No custom response replacement function was registered for label: {}",
292                    label
293                );
294            }
295        }
296
297        ready(Ok(LoggerMiddleware {
298            service,
299            inner: Rc::clone(&self.0),
300        }))
301    }
302}
303
304/// Logger middleware service.
305pub struct LoggerMiddleware<S> {
306    inner: Rc<Inner>,
307    service: S,
308}
309
310impl<S, B> Service<ServiceRequest> for LoggerMiddleware<S>
311where
312    S: Service<ServiceRequest, Response = ServiceResponse<B>, Error = Error>,
313    B: MessageBody,
314{
315    type Response = ServiceResponse<StreamLog<B>>;
316    type Error = Error;
317    type Future = LoggerResponse<S, B>;
318
319    actix_service::forward_ready!(service);
320
321    fn call(&self, req: ServiceRequest) -> Self::Future {
322        let excluded = self.inner.exclude.contains(req.path())
323            || self
324                .inner
325                .exclude_regex
326                .iter()
327                .any(|r| r.is_match(req.path()));
328
329        if excluded {
330            LoggerResponse {
331                fut: self.service.call(req),
332                format: None,
333                time: OffsetDateTime::now_utc(),
334                log_target: Cow::Borrowed(""),
335                log_level: self.inner.log_level,
336                _phantom: PhantomData,
337            }
338        } else {
339            let now = OffsetDateTime::now_utc();
340            let mut format = self.inner.format.clone();
341
342            for unit in &mut format.0 {
343                unit.render_request(now, &req);
344            }
345
346            LoggerResponse {
347                fut: self.service.call(req),
348                format: Some(format),
349                time: now,
350                log_target: self.inner.log_target.clone(),
351                log_level: self.inner.log_level,
352                _phantom: PhantomData,
353            }
354        }
355    }
356}
357
358pin_project! {
359    pub struct LoggerResponse<S, B>
360    where
361        B: MessageBody,
362        S: Service<ServiceRequest>,
363    {
364        #[pin]
365        fut: S::Future,
366        time: OffsetDateTime,
367        format: Option<Format>,
368        log_target: Cow<'static, str>,
369        log_level: Level,
370        _phantom: PhantomData<B>,
371    }
372}
373
374impl<S, B> Future for LoggerResponse<S, B>
375where
376    B: MessageBody,
377    S: Service<ServiceRequest, Response = ServiceResponse<B>, Error = Error>,
378{
379    type Output = Result<ServiceResponse<StreamLog<B>>, Error>;
380
381    fn poll(self: Pin<&mut Self>, cx: &mut Context<'_>) -> Poll<Self::Output> {
382        let this = self.project();
383
384        let res = match ready!(this.fut.poll(cx)) {
385            Ok(res) => res,
386            Err(err) => return Poll::Ready(Err(err)),
387        };
388
389        if let Some(error) = res.response().error() {
390            debug!("Error in response: {:?}", error);
391        }
392
393        let res = if let Some(ref mut format) = this.format {
394            // to avoid polluting all the Logger types with the body parameter we swap the body
395            // out temporarily since it's not usable in custom response functions anyway
396
397            let (req, res) = res.into_parts();
398            let (res, body) = res.into_parts();
399
400            let temp_res = ServiceResponse::new(req, res.map_into_boxed_body());
401
402            for unit in &mut format.0 {
403                unit.render_response(&temp_res);
404            }
405
406            // re-construct original service response
407            let (req, res) = temp_res.into_parts();
408            ServiceResponse::new(req, res.set_body(body))
409        } else {
410            res
411        };
412
413        let time = *this.time;
414        let format = this.format.take();
415        let log_target = this.log_target.clone();
416        let log_level = *this.log_level;
417
418        Poll::Ready(Ok(res.map_body(move |_, body| StreamLog {
419            body,
420            time,
421            format,
422            size: 0,
423            log_target,
424            log_level,
425        })))
426    }
427}
428
429pin_project! {
430    pub struct StreamLog<B> {
431        #[pin]
432        body: B,
433        format: Option<Format>,
434        size: usize,
435        time: OffsetDateTime,
436        log_target: Cow<'static, str>,
437        log_level: Level
438    }
439
440    impl<B> PinnedDrop for StreamLog<B> {
441        fn drop(this: Pin<&mut Self>) {
442            if let Some(ref format) = this.format {
443                let render = |fmt: &mut fmt::Formatter<'_>| {
444                    for unit in &format.0 {
445                        unit.render(fmt, this.size, this.time)?;
446                    }
447                    Ok(())
448                };
449
450                log::log!(
451                    target: this.log_target.as_ref(),
452                    this.log_level,
453                    "{}", FormatDisplay(&render)
454                );
455            }
456        }
457    }
458}
459
460impl<B: MessageBody> MessageBody for StreamLog<B> {
461    type Error = B::Error;
462
463    #[inline]
464    fn size(&self) -> BodySize {
465        self.body.size()
466    }
467
468    fn poll_next(
469        self: Pin<&mut Self>,
470        cx: &mut Context<'_>,
471    ) -> Poll<Option<Result<Bytes, Self::Error>>> {
472        let this = self.project();
473
474        match ready!(this.body.poll_next(cx)) {
475            Some(Ok(chunk)) => {
476                *this.size += chunk.len();
477                Poll::Ready(Some(Ok(chunk)))
478            }
479            Some(Err(err)) => Poll::Ready(Some(Err(err))),
480            None => Poll::Ready(None),
481        }
482    }
483}
484
485/// A formatting style for the `Logger` consisting of multiple concatenated `FormatText` items.
486#[derive(Debug, Clone)]
487struct Format(Vec<FormatText>);
488
489impl Default for Format {
490    /// Return the default formatting style for the `Logger`:
491    fn default() -> Format {
492        Format::new(r#"%a "%r" %s %b "%{Referer}i" "%{User-Agent}i" %T"#)
493    }
494}
495
496impl Format {
497    /// Create a `Format` from a format string.
498    ///
499    /// Returns `None` if the format string syntax is incorrect.
500    pub fn new(s: &str) -> Format {
501        log::trace!("Access log format: {}", s);
502        let fmt = Regex::new(r"%(\{([A-Za-z0-9\-_]+)\}([aioe]|x[io])|[%atPrUsbTD]?)").unwrap();
503
504        let mut idx = 0;
505        let mut results = Vec::new();
506        for cap in fmt.captures_iter(s) {
507            let m = cap.get(0).unwrap();
508            let pos = m.start();
509            if idx != pos {
510                results.push(FormatText::Str(s[idx..pos].to_owned()));
511            }
512            idx = m.end();
513
514            if let Some(key) = cap.get(2) {
515                results.push(match cap.get(3).unwrap().as_str() {
516                    "a" => {
517                        if key.as_str() == "r" {
518                            FormatText::RealIpRemoteAddr
519                        } else {
520                            unreachable!("regex and code mismatch")
521                        }
522                    }
523                    "i" => FormatText::RequestHeader(HeaderName::try_from(key.as_str()).unwrap()),
524                    "o" => FormatText::ResponseHeader(HeaderName::try_from(key.as_str()).unwrap()),
525                    "e" => FormatText::EnvironHeader(key.as_str().to_owned()),
526                    "xi" => FormatText::CustomRequest(key.as_str().to_owned(), None),
527                    "xo" => FormatText::CustomResponse(key.as_str().to_owned(), None),
528                    _ => unreachable!(),
529                })
530            } else {
531                let m = cap.get(1).unwrap();
532                results.push(match m.as_str() {
533                    "%" => FormatText::Percent,
534                    "a" => FormatText::RemoteAddr,
535                    "t" => FormatText::RequestTime,
536                    "r" => FormatText::RequestLine,
537                    "s" => FormatText::ResponseStatus,
538                    "b" => FormatText::ResponseSize,
539                    "U" => FormatText::UrlPath,
540                    "T" => FormatText::Time,
541                    "D" => FormatText::TimeMillis,
542                    _ => FormatText::Str(m.as_str().to_owned()),
543                });
544            }
545        }
546        if idx != s.len() {
547            results.push(FormatText::Str(s[idx..].to_owned()));
548        }
549
550        Format(results)
551    }
552}
553
554/// A string of text to be logged.
555///
556/// This is either one of the data fields supported by the `Logger`, or a custom `String`.
557#[non_exhaustive]
558#[derive(Debug, Clone)]
559enum FormatText {
560    Str(String),
561    Percent,
562    RequestLine,
563    RequestTime,
564    ResponseStatus,
565    ResponseSize,
566    Time,
567    TimeMillis,
568    RemoteAddr,
569    RealIpRemoteAddr,
570    UrlPath,
571    RequestHeader(HeaderName),
572    ResponseHeader(HeaderName),
573    EnvironHeader(String),
574    CustomRequest(String, Option<CustomRequestFn>),
575    CustomResponse(String, Option<CustomResponseFn>),
576}
577
578#[derive(Clone)]
579struct CustomRequestFn {
580    inner_fn: Rc<dyn Fn(&ServiceRequest) -> String>,
581}
582
583impl CustomRequestFn {
584    fn call(&self, req: &ServiceRequest) -> String {
585        (self.inner_fn)(req)
586    }
587}
588
589impl fmt::Debug for CustomRequestFn {
590    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
591        f.write_str("custom_request_fn")
592    }
593}
594
595#[derive(Clone)]
596struct CustomResponseFn {
597    inner_fn: Rc<dyn Fn(&ServiceResponse) -> String>,
598}
599
600impl CustomResponseFn {
601    fn call(&self, res: &ServiceResponse) -> String {
602        (self.inner_fn)(res)
603    }
604}
605
606impl fmt::Debug for CustomResponseFn {
607    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
608        f.write_str("custom_response_fn")
609    }
610}
611
612impl FormatText {
613    fn render(
614        &self,
615        fmt: &mut fmt::Formatter<'_>,
616        size: usize,
617        entry_time: OffsetDateTime,
618    ) -> Result<(), fmt::Error> {
619        match self {
620            FormatText::Str(ref string) => fmt.write_str(string),
621            FormatText::Percent => "%".fmt(fmt),
622            FormatText::ResponseSize => size.fmt(fmt),
623            FormatText::Time => {
624                let rt = OffsetDateTime::now_utc() - entry_time;
625                let rt = rt.as_seconds_f64();
626                fmt.write_fmt(format_args!("{:.6}", rt))
627            }
628            FormatText::TimeMillis => {
629                let rt = OffsetDateTime::now_utc() - entry_time;
630                let rt = (rt.whole_nanoseconds() as f64) / 1_000_000.0;
631                fmt.write_fmt(format_args!("{:.6}", rt))
632            }
633            FormatText::EnvironHeader(ref name) => {
634                if let Ok(val) = env::var(name) {
635                    fmt.write_fmt(format_args!("{}", val))
636                } else {
637                    "-".fmt(fmt)
638                }
639            }
640            _ => Ok(()),
641        }
642    }
643
644    fn render_response(&mut self, res: &ServiceResponse) {
645        match self {
646            FormatText::ResponseStatus => {
647                *self = FormatText::Str(format!("{}", res.status().as_u16()))
648            }
649
650            FormatText::ResponseHeader(ref name) => {
651                let s = if let Some(val) = res.headers().get(name) {
652                    String::from_utf8_lossy(val.as_bytes()).into_owned()
653                } else {
654                    "-".to_owned()
655                };
656                *self = FormatText::Str(s.to_string())
657            }
658
659            FormatText::CustomResponse(_, res_fn) => {
660                let text = match res_fn {
661                    Some(res_fn) => FormatText::Str(res_fn.call(res)),
662                    None => FormatText::Str("-".to_owned()),
663                };
664
665                *self = text;
666            }
667
668            _ => {}
669        }
670    }
671
672    fn render_request(&mut self, now: OffsetDateTime, req: &ServiceRequest) {
673        match self {
674            FormatText::RequestLine => {
675                *self = if req.query_string().is_empty() {
676                    FormatText::Str(format!(
677                        "{} {} {:?}",
678                        req.method(),
679                        req.path(),
680                        req.version()
681                    ))
682                } else {
683                    FormatText::Str(format!(
684                        "{} {}?{} {:?}",
685                        req.method(),
686                        req.path(),
687                        req.query_string(),
688                        req.version()
689                    ))
690                };
691            }
692            FormatText::UrlPath => *self = FormatText::Str(req.path().to_string()),
693            FormatText::RequestTime => *self = FormatText::Str(now.format(&Rfc3339).unwrap()),
694            FormatText::RequestHeader(ref name) => {
695                let s = if let Some(val) = req.headers().get(name) {
696                    String::from_utf8_lossy(val.as_bytes()).into_owned()
697                } else {
698                    "-".to_owned()
699                };
700                *self = FormatText::Str(s);
701            }
702            FormatText::RemoteAddr => {
703                let s = if let Some(peer) = req.connection_info().peer_addr() {
704                    FormatText::Str((*peer).to_string())
705                } else {
706                    FormatText::Str("-".to_string())
707                };
708                *self = s;
709            }
710            FormatText::RealIpRemoteAddr => {
711                let s = if let Some(remote) = req.connection_info().realip_remote_addr() {
712                    FormatText::Str(remote.to_string())
713                } else {
714                    FormatText::Str("-".to_string())
715                };
716                *self = s;
717            }
718            FormatText::CustomRequest(_, request_fn) => {
719                let s = match request_fn {
720                    Some(f) => FormatText::Str(f.call(req)),
721                    None => FormatText::Str("-".to_owned()),
722                };
723
724                *self = s;
725            }
726            _ => {}
727        }
728    }
729}
730
731/// Converter to get a String from something that writes to a Formatter.
732pub(crate) struct FormatDisplay<'a>(&'a dyn Fn(&mut fmt::Formatter<'_>) -> Result<(), fmt::Error>);
733
734impl fmt::Display for FormatDisplay<'_> {
735    fn fmt(&self, fmt: &mut fmt::Formatter<'_>) -> Result<(), fmt::Error> {
736        (self.0)(fmt)
737    }
738}
739
740#[cfg(test)]
741mod tests {
742    use actix_service::IntoService;
743    use actix_utils::future::ok;
744
745    use super::*;
746    use crate::{
747        http::{header, StatusCode},
748        test::{self, TestRequest},
749        HttpResponse,
750    };
751
752    #[actix_rt::test]
753    async fn test_logger() {
754        let srv = |req: ServiceRequest| {
755            ok(req.into_response(
756                HttpResponse::build(StatusCode::OK)
757                    .insert_header(("X-Test", "ttt"))
758                    .finish(),
759            ))
760        };
761        let logger = Logger::new("%% %{User-Agent}i %{X-Test}o %{HOME}e %D test");
762
763        let srv = logger.new_transform(srv.into_service()).await.unwrap();
764
765        let req = TestRequest::default()
766            .insert_header((
767                header::USER_AGENT,
768                header::HeaderValue::from_static("ACTIX-WEB"),
769            ))
770            .to_srv_request();
771        let _res = srv.call(req).await;
772    }
773
774    #[actix_rt::test]
775    async fn test_logger_exclude_regex() {
776        let srv = |req: ServiceRequest| {
777            ok(req.into_response(
778                HttpResponse::build(StatusCode::OK)
779                    .insert_header(("X-Test", "ttt"))
780                    .finish(),
781            ))
782        };
783        let logger =
784            Logger::new("%% %{User-Agent}i %{X-Test}o %{HOME}e %D test").exclude_regex("\\w");
785
786        let srv = logger.new_transform(srv.into_service()).await.unwrap();
787
788        let req = TestRequest::default()
789            .insert_header((
790                header::USER_AGENT,
791                header::HeaderValue::from_static("ACTIX-WEB"),
792            ))
793            .to_srv_request();
794        let _res = srv.call(req).await.unwrap();
795    }
796
797    #[actix_rt::test]
798    async fn test_escape_percent() {
799        let mut format = Format::new("%%{r}a");
800
801        let req = TestRequest::default()
802            .insert_header((
803                header::FORWARDED,
804                header::HeaderValue::from_static("for=192.0.2.60;proto=http;by=203.0.113.43"),
805            ))
806            .to_srv_request();
807
808        let now = OffsetDateTime::now_utc();
809        for unit in &mut format.0 {
810            unit.render_request(now, &req);
811        }
812
813        let req = TestRequest::default().to_http_request();
814        let res = ServiceResponse::new(req, HttpResponse::Ok().finish());
815        for unit in &mut format.0 {
816            unit.render_response(&res);
817        }
818
819        let entry_time = OffsetDateTime::now_utc();
820        let render = |fmt: &mut fmt::Formatter<'_>| {
821            for unit in &format.0 {
822                unit.render(fmt, 1024, entry_time)?;
823            }
824            Ok(())
825        };
826        let s = format!("{}", FormatDisplay(&render));
827        assert_eq!(s, "%{r}a");
828    }
829
830    #[actix_rt::test]
831    async fn test_url_path() {
832        let mut format = Format::new("%T %U");
833        let req = TestRequest::default()
834            .insert_header((
835                header::USER_AGENT,
836                header::HeaderValue::from_static("ACTIX-WEB"),
837            ))
838            .uri("/test/route/yeah")
839            .to_srv_request();
840
841        let now = OffsetDateTime::now_utc();
842        for unit in &mut format.0 {
843            unit.render_request(now, &req);
844        }
845
846        let req = TestRequest::default().to_http_request();
847        let res = ServiceResponse::new(req, HttpResponse::Ok().force_close().finish());
848        for unit in &mut format.0 {
849            unit.render_response(&res);
850        }
851
852        let render = |fmt: &mut fmt::Formatter<'_>| {
853            for unit in &format.0 {
854                unit.render(fmt, 1024, now)?;
855            }
856            Ok(())
857        };
858        let s = format!("{}", FormatDisplay(&render));
859        assert!(s.contains("/test/route/yeah"));
860    }
861
862    #[actix_rt::test]
863    async fn test_default_format() {
864        let mut format = Format::default();
865
866        let req = TestRequest::default()
867            .insert_header((
868                header::USER_AGENT,
869                header::HeaderValue::from_static("ACTIX-WEB"),
870            ))
871            .peer_addr("127.0.0.1:8081".parse().unwrap())
872            .to_srv_request();
873
874        let now = OffsetDateTime::now_utc();
875        for unit in &mut format.0 {
876            unit.render_request(now, &req);
877        }
878
879        let req = TestRequest::default().to_http_request();
880        let res = ServiceResponse::new(req, HttpResponse::Ok().force_close().finish());
881        for unit in &mut format.0 {
882            unit.render_response(&res);
883        }
884
885        let entry_time = OffsetDateTime::now_utc();
886        let render = |fmt: &mut fmt::Formatter<'_>| {
887            for unit in &format.0 {
888                unit.render(fmt, 1024, entry_time)?;
889            }
890            Ok(())
891        };
892        let s = format!("{}", FormatDisplay(&render));
893        assert!(s.contains("GET / HTTP/1.1"));
894        assert!(s.contains("127.0.0.1"));
895        assert!(s.contains("200 1024"));
896        assert!(s.contains("ACTIX-WEB"));
897    }
898
899    #[actix_rt::test]
900    async fn test_request_time_format() {
901        let mut format = Format::new("%t");
902        let req = TestRequest::default().to_srv_request();
903
904        let now = OffsetDateTime::now_utc();
905        for unit in &mut format.0 {
906            unit.render_request(now, &req);
907        }
908
909        let req = TestRequest::default().to_http_request();
910        let res = ServiceResponse::new(req, HttpResponse::Ok().force_close().finish());
911        for unit in &mut format.0 {
912            unit.render_response(&res);
913        }
914
915        let render = |fmt: &mut fmt::Formatter<'_>| {
916            for unit in &format.0 {
917                unit.render(fmt, 1024, now)?;
918            }
919            Ok(())
920        };
921        let s = format!("{}", FormatDisplay(&render));
922        assert!(s.contains(&now.format(&Rfc3339).unwrap()));
923    }
924
925    #[actix_rt::test]
926    async fn test_remote_addr_format() {
927        let mut format = Format::new("%{r}a");
928
929        let req = TestRequest::default()
930            .insert_header((
931                header::FORWARDED,
932                header::HeaderValue::from_static("for=192.0.2.60;proto=http;by=203.0.113.43"),
933            ))
934            .to_srv_request();
935
936        let now = OffsetDateTime::now_utc();
937        for unit in &mut format.0 {
938            unit.render_request(now, &req);
939        }
940
941        let req = TestRequest::default().to_http_request();
942        let res = ServiceResponse::new(req, HttpResponse::Ok().finish());
943        for unit in &mut format.0 {
944            unit.render_response(&res);
945        }
946
947        let entry_time = OffsetDateTime::now_utc();
948        let render = |fmt: &mut fmt::Formatter<'_>| {
949            for unit in &format.0 {
950                unit.render(fmt, 1024, entry_time)?;
951            }
952            Ok(())
953        };
954        let s = format!("{}", FormatDisplay(&render));
955        assert!(s.contains("192.0.2.60"));
956    }
957
958    #[actix_rt::test]
959    async fn test_custom_closure_req_log() {
960        let mut logger = Logger::new("test %{CUSTOM}xi")
961            .custom_request_replace("CUSTOM", |_req: &ServiceRequest| -> String {
962                String::from("custom_log")
963            });
964        let mut unit = Rc::get_mut(&mut logger.0).unwrap().format.0[1].clone();
965
966        let label = match &unit {
967            FormatText::CustomRequest(label, _) => label,
968            ft => panic!("expected CustomRequest, found {:?}", ft),
969        };
970
971        assert_eq!(label, "CUSTOM");
972
973        let req = TestRequest::default().to_srv_request();
974        let now = OffsetDateTime::now_utc();
975
976        unit.render_request(now, &req);
977
978        let render = |fmt: &mut fmt::Formatter<'_>| unit.render(fmt, 1024, now);
979
980        let log_output = FormatDisplay(&render).to_string();
981        assert_eq!(log_output, "custom_log");
982    }
983
984    #[actix_rt::test]
985    async fn test_custom_closure_response_log() {
986        let mut logger = Logger::new("test %{CUSTOM}xo").custom_response_replace(
987            "CUSTOM",
988            |res: &ServiceResponse| -> String {
989                if res.status().as_u16() == 200 {
990                    String::from("custom_log")
991                } else {
992                    String::from("-")
993                }
994            },
995        );
996        let mut unit = Rc::get_mut(&mut logger.0).unwrap().format.0[1].clone();
997
998        let label = match &unit {
999            FormatText::CustomResponse(label, _) => label,
1000            ft => panic!("expected CustomResponse, found {:?}", ft),
1001        };
1002
1003        assert_eq!(label, "CUSTOM");
1004
1005        let req = TestRequest::default().to_http_request();
1006        let resp_ok = ServiceResponse::new(req, HttpResponse::Ok().finish());
1007        let now = OffsetDateTime::now_utc();
1008        unit.render_response(&resp_ok);
1009
1010        let render = |fmt: &mut fmt::Formatter<'_>| unit.render(fmt, 1024, now);
1011
1012        let log_output = FormatDisplay(&render).to_string();
1013        assert_eq!(log_output, "custom_log");
1014    }
1015
1016    #[actix_rt::test]
1017    async fn test_closure_logger_in_middleware() {
1018        let captured = "custom log replacement";
1019
1020        let logger = Logger::new("%{CUSTOM}xi")
1021            .custom_request_replace("CUSTOM", move |_req: &ServiceRequest| -> String {
1022                captured.to_owned()
1023            });
1024
1025        let srv = logger.new_transform(test::ok_service()).await.unwrap();
1026
1027        let req = TestRequest::default().to_srv_request();
1028        srv.call(req).await.unwrap();
1029    }
1030}
actix_web/middleware/logger.rs

actix_web/middleware/
logger.rs
