actix_contrib_logger/middleware/
logger.rs

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

actix_contrib_logger/middleware/
logger.rs
