ntex/web/middleware/
logger.rs

1//! Request logging middleware
2#![allow(clippy::cast_precision_loss)]
3use std::task::{Context, Poll};
4use std::{env, error::Error, fmt, fmt::Display, rc::Rc, time};
5
6use regex::Regex;
7
8use crate::http::body::{Body, BodySize, MessageBody, ResponseBody};
9use crate::http::header::HeaderName;
10use crate::service::{Ctx, Middleware, Service};
11use crate::util::{Bytes, HashSet};
12use crate::web::{HttpResponse, WebRequest, WebResponse};
13
14/// `Middleware` for logging request and response info to the terminal.
15///
16/// `Logger` middleware uses standard log crate to log information. You should
17/// enable logger for `ntex` package to see access log.
18/// ([`env_logger`](https://docs.rs/env_logger/*/env_logger/) or similar)
19///
20/// ## Usage
21///
22/// Create `Logger` middleware with the specified `format`.
23/// Default `Logger` could be created with `default` method, it uses the
24/// default format:
25///
26/// ```ignore
27///  %a "%r" %s %b "%{Referer}i" "%{User-Agent}i" %T
28/// ```
29/// ```rust
30/// use ntex::web::App;
31/// use ntex::web::middleware::Logger;
32///
33/// fn main() {
34///     let app = App::default()
35///         .middleware(Logger::default())
36///         .middleware(Logger::new("%a %{User-Agent}i"));
37/// }
38/// ```
39///
40/// ## Format
41///
42/// `%%`  The percent sign
43///
44/// `%a`  Remote IP-address (IP-address of proxy if using reverse proxy)
45///
46/// `%t`  Time when the request was started to process (in HTTP-date format,
47/// e.g. `Thu, 04 Sep 2025 15:33:20 GMT`)
48///
49/// `%r`  First line of request
50///
51/// `%s`  Response status code
52///
53/// `%b`  Size of response in bytes, excluding HTTP headers
54///
55/// `%T`  Time taken to serve the request, in seconds with six decimal places
56///
57/// `%D`  Time taken to serve the request, in milliseconds with six decimal
58/// places
59///
60/// `%U`  Request URL path, without the query string
61///
62/// `%{FOO}i`  `request.headers["FOO"]`
63///
64/// `%{FOO}o`  `response.headers["FOO"]`
65///
66/// `%{FOO}e`  `os.environ["FOO"]`
67///
68#[derive(Debug)]
69pub struct Logger {
70    inner: Rc<Inner>,
71}
72
73#[derive(Debug)]
74struct Inner {
75    format: Format,
76    exclude: HashSet<String>,
77}
78
79impl Logger {
80    /// Create `Logger` middleware with the specified `format`.
81    pub fn new(format: &str) -> Logger {
82        Logger {
83            inner: Rc::new(Inner {
84                format: Format::new(format),
85                exclude: HashSet::default(),
86            }),
87        }
88    }
89
90    #[must_use]
91    /// Ignore and do not log access info for specified path.
92    pub fn exclude<T: Into<String>>(mut self, path: T) -> Self {
93        Rc::get_mut(&mut self.inner)
94            .unwrap()
95            .exclude
96            .insert(path.into());
97        self
98    }
99}
100
101impl Default for Logger {
102    /// Create `Logger` middleware with format:
103    ///
104    /// ```ignore
105    /// %a "%r" %s %b "%{Referer}i" "%{User-Agent}i" %T
106    /// ```
107    fn default() -> Self {
108        Logger {
109            inner: Rc::new(Inner {
110                format: Format::default(),
111                exclude: HashSet::default(),
112            }),
113        }
114    }
115}
116
117impl<S, St> Middleware<S, St> for Logger {
118    type Service = LoggerMiddleware<S>;
119
120    fn create(&self, _: &St, service: S) -> Self::Service {
121        LoggerMiddleware {
122            service,
123            inner: self.inner.clone(),
124        }
125    }
126}
127
128#[derive(Debug)]
129/// Logger middleware
130pub struct LoggerMiddleware<S> {
131    inner: Rc<Inner>,
132    service: S,
133}
134
135impl<S, St, In> Service<St, WebRequest<In>> for LoggerMiddleware<S>
136where
137    S: Service<St, WebRequest<In>, Res = WebResponse>,
138{
139    type Res = WebResponse;
140    type Error = S::Error;
141
142    crate::forward_ready!(St, service);
143    crate::forward_shutdown!(St, service);
144
145    async fn call(
146        &self,
147        req: WebRequest<In>,
148        ctx: Ctx<'_, Self, St>,
149    ) -> Result<Self::Res, S::Error> {
150        if self.inner.exclude.contains(req.path()) {
151            ctx.call(&self.service, req).await
152        } else {
153            let time = time::SystemTime::now();
154            let mut values = self.inner.format.render_request(time, &req);
155
156            let res = ctx.call(&self.service, req).await?;
157            self.inner
158                .format
159                .render_response(res.response(), &mut values);
160
161            let inner = self.inner.clone();
162            Ok(res.map_body(move |_, body| {
163                ResponseBody::Other(Body::from_message(StreamLog {
164                    body,
165                    time,
166                    inner,
167                    values,
168                    size: 0,
169                }))
170            }))
171        }
172    }
173}
174
175struct StreamLog {
176    body: ResponseBody<Body>,
177    inner: Rc<Inner>,
178    values: Vec<Option<String>>,
179    size: usize,
180    time: time::SystemTime,
181}
182
183impl Drop for StreamLog {
184    fn drop(&mut self) {
185        let render = |fmt: &mut fmt::Formatter<'_>| {
186            self.inner
187                .format
188                .render(fmt, &self.values, self.size, self.time)
189        };
190        log::info!("{}", FormatDisplay(&render));
191    }
192}
193
194impl MessageBody for StreamLog {
195    fn size(&self) -> BodySize {
196        self.body.size()
197    }
198
199    fn poll_next_chunk(
200        &mut self,
201        cx: &mut Context<'_>,
202    ) -> Poll<Option<Result<Bytes, Rc<dyn Error>>>> {
203        match self.body.poll_next_chunk(cx) {
204            Poll::Ready(Some(Ok(chunk))) => {
205                self.size += chunk.len();
206                Poll::Ready(Some(Ok(chunk)))
207            }
208            val => val,
209        }
210    }
211}
212
213/// A formatting style for the `Logger`, consisting of multiple
214/// `FormatText`s concatenated into one line.
215#[derive(Debug)]
216#[doc(hidden)]
217struct Format(Vec<FormatText>);
218
219impl Default for Format {
220    /// Return the default formatting style for the `Logger`:
221    fn default() -> Format {
222        Format::new(r#"%a "%r" %s %b "%{Referer}i" "%{User-Agent}i" %T"#)
223    }
224}
225
226impl Format {
227    /// Create a `Format` from a format string.
228    ///
229    /// Text that is not a recognized format specifier is logged verbatim.
230    fn new(s: &str) -> Format {
231        log::trace!("Access log format: {s}");
232        let fmt = Regex::new(r"%(\{([A-Za-z0-9\-_]+)\}([ioe])|[%atrUsbTD]?)").unwrap();
233
234        let mut idx = 0;
235        let mut results = Vec::new();
236        for cap in fmt.captures_iter(s) {
237            let m = cap.get(0).unwrap();
238            let pos = m.start();
239            if idx != pos {
240                results.push(FormatText::Str(s[idx..pos].to_owned()));
241            }
242            idx = m.end();
243
244            if let Some(key) = cap.get(2) {
245                results.push(match cap.get(3).unwrap().as_str() {
246                    "i" => FormatText::RequestHeader(HeaderName::try_from(key.as_str()).unwrap()),
247                    "o" => FormatText::ResponseHeader(HeaderName::try_from(key.as_str()).unwrap()),
248                    "e" => FormatText::EnvironHeader(key.as_str().to_owned()),
249                    _ => unreachable!(),
250                });
251            } else {
252                let m = cap.get(1).unwrap();
253                results.push(match m.as_str() {
254                    "%" => FormatText::Percent,
255                    "a" => FormatText::RemoteAddr,
256                    "t" => FormatText::RequestTime,
257                    "r" => FormatText::RequestLine,
258                    "s" => FormatText::ResponseStatus,
259                    "b" => FormatText::ResponseSize,
260                    "U" => FormatText::UrlPath,
261                    "T" => FormatText::Time,
262                    "D" => FormatText::TimeMillis,
263                    _ => FormatText::Str(m.as_str().to_owned()),
264                });
265            }
266        }
267        if idx != s.len() {
268            results.push(FormatText::Str(s[idx..].to_owned()));
269        }
270
271        Format(results)
272    }
273
274    /// Renders the request fields, one entry per unit.
275    fn render_request<R>(&self, now: time::SystemTime, req: &WebRequest<R>) -> Vec<Option<String>> {
276        self.0
277            .iter()
278            .map(|unit| unit.render_request(now, req))
279            .collect()
280    }
281
282    /// Renders the response fields into the entries of `values`.
283    fn render_response<B>(&self, res: &HttpResponse<B>, values: &mut [Option<String>]) {
284        for (unit, value) in self.0.iter().zip(values) {
285            if let Some(s) = unit.render_response(res) {
286                *value = Some(s);
287            }
288        }
289    }
290
291    fn render(
292        &self,
293        fmt: &mut fmt::Formatter<'_>,
294        values: &[Option<String>],
295        size: usize,
296        entry_time: time::SystemTime,
297    ) -> Result<(), fmt::Error> {
298        for (idx, unit) in self.0.iter().enumerate() {
299            if let Some(Some(value)) = values.get(idx) {
300                fmt.write_str(value)?;
301            } else {
302                unit.render(fmt, size, entry_time)?;
303            }
304        }
305        Ok(())
306    }
307}
308
309/// A string of text to be logged. This is either one of the data
310/// fields supported by the `Logger`, or a custom `String`.
311#[doc(hidden)]
312#[derive(Debug)]
313enum FormatText {
314    Str(String),
315    Percent,
316    RequestLine,
317    RequestTime,
318    ResponseStatus,
319    ResponseSize,
320    Time,
321    TimeMillis,
322    RemoteAddr,
323    UrlPath,
324    RequestHeader(HeaderName),
325    ResponseHeader(HeaderName),
326    EnvironHeader(String),
327}
328
329impl FormatText {
330    fn render(
331        &self,
332        fmt: &mut fmt::Formatter<'_>,
333        size: usize,
334        entry_time: time::SystemTime,
335    ) -> Result<(), fmt::Error> {
336        match *self {
337            FormatText::Str(ref string) => fmt.write_str(string),
338            FormatText::Percent => "%".fmt(fmt),
339            FormatText::ResponseSize => size.fmt(fmt),
340            FormatText::Time => {
341                let rt = entry_time.elapsed().unwrap();
342                let rt = rt.as_secs_f64();
343                fmt.write_fmt(format_args!("{rt:.6}"))
344            }
345            FormatText::TimeMillis => {
346                let rt = entry_time.elapsed().unwrap();
347                let rt = (rt.as_nanos() as f64) / 1_000_000.0;
348                fmt.write_fmt(format_args!("{rt:.6}"))
349            }
350            FormatText::EnvironHeader(ref name) => {
351                if let Ok(val) = env::var(name) {
352                    fmt.write_fmt(format_args!("{val}"))
353                } else {
354                    "-".fmt(fmt)
355                }
356            }
357            _ => Ok(()),
358        }
359    }
360
361    fn render_response<B>(&self, res: &HttpResponse<B>) -> Option<String> {
362        match *self {
363            FormatText::ResponseStatus => Some(res.status().as_u16().to_string()),
364            FormatText::ResponseHeader(ref name) => {
365                let s = if let Some(val) = res.headers().get(name) {
366                    val.to_str().unwrap_or("-")
367                } else {
368                    "-"
369                };
370                Some(s.to_string())
371            }
372            _ => None,
373        }
374    }
375
376    fn render_request<R>(&self, now: time::SystemTime, req: &WebRequest<R>) -> Option<String> {
377        match *self {
378            FormatText::RequestLine => {
379                let q = req.query_string();
380                Some(if q.is_empty() {
381                    format!("{} {} {:?}", req.method(), req.path(), req.version())
382                } else {
383                    format!("{} {}?{} {:?}", req.method(), req.path(), q, req.version())
384                })
385            }
386            FormatText::UrlPath => Some(req.path().to_string()),
387            FormatText::RequestTime => Some(httpdate::HttpDate::from(now).to_string()),
388            FormatText::RequestHeader(ref name) => {
389                let s = if let Some(val) = req.headers().get(name) {
390                    val.to_str().unwrap_or("-")
391                } else {
392                    "-"
393                };
394                Some(s.to_string())
395            }
396            FormatText::RemoteAddr => Some(
397                req.connection_info()
398                    .remote()
399                    .map_or_else(|| "-".to_string(), ToString::to_string),
400            ),
401            _ => None,
402        }
403    }
404}
405
406pub(crate) struct FormatDisplay<'a>(&'a dyn Fn(&mut fmt::Formatter<'_>) -> Result<(), fmt::Error>);
407
408impl fmt::Display for FormatDisplay<'_> {
409    fn fmt(&self, fmt: &mut fmt::Formatter<'_>) -> Result<(), fmt::Error> {
410        (self.0)(fmt)
411    }
412}
413
414#[cfg(test)]
415mod tests {
416    use std::convert::Infallible;
417
418    use super::*;
419    use crate::http::{StatusCode, header};
420    use crate::web::{test, test::TestRequest};
421    use crate::{fn_service, service::Pipeline, util::lazy};
422
423    #[crate::rt_test]
424    async fn test_logger() {
425        let srv = fn_service(async move |req: WebRequest<()>| {
426            Ok::<_, Infallible>(
427                req.into_response(
428                    HttpResponse::builder(StatusCode::OK)
429                        .header("X-Test", "ttt")
430                        .body("TEST"),
431                ),
432            )
433        });
434        let _logger = Logger::default();
435        let logger =
436            Logger::new("%% %{User-Agent}i %{X-Test}o %{HOME}e %D %% test").exclude("/test");
437
438        let srv = Pipeline::new((), Middleware::create(&logger, &(), srv));
439        assert!(lazy(|cx| srv.poll_ready(cx).is_ready()).await);
440        assert!(lazy(|cx| srv.poll_shutdown(cx).is_ready()).await);
441
442        let req =
443            TestRequest::with_header(header::USER_AGENT, header::HeaderValue::from_static("NTEX"))
444                .to_srv_request();
445        let res = srv.call(req).await.unwrap();
446        let body = test::read_body(res).await;
447        assert_eq!(body, Bytes::from_static(b"TEST"));
448        assert_eq!(body.size(), BodySize::Sized(4));
449        drop(body);
450
451        let req = TestRequest::with_uri("/test").to_srv_request();
452        let res = srv.call(req).await.unwrap();
453        let body = test::read_body(res).await;
454        assert_eq!(body, Bytes::from_static(b"TEST"));
455    }
456
457    #[crate::rt_test]
458    async fn test_request_line() {
459        let format = Format::new("%r");
460        let req =
461            TestRequest::with_header(header::USER_AGENT, header::HeaderValue::from_static("NTEX"))
462                .uri("/test/route/yeah?q=test")
463                .to_srv_request();
464
465        let now = time::SystemTime::now();
466        let mut values = format.render_request(now, &req);
467
468        let resp = HttpResponse::builder(StatusCode::OK).force_close().build();
469        format.render_response(&resp, &mut values);
470
471        let render = |fmt: &mut fmt::Formatter<'_>| format.render(fmt, &values, 1024, now);
472        let s = format!("{}", FormatDisplay(&render));
473        assert_eq!(s, "GET /test/route/yeah?q=test HTTP/1.1");
474    }
475
476    #[crate::rt_test]
477    async fn test_url_path() {
478        let format = Format::new("%T %U");
479        let req =
480            TestRequest::with_header(header::USER_AGENT, header::HeaderValue::from_static("NTEX"))
481                .uri("/test/route/yeah?q=test")
482                .to_srv_request();
483
484        let now = time::SystemTime::now();
485        let mut values = format.render_request(now, &req);
486
487        let resp = HttpResponse::builder(StatusCode::OK).force_close().build();
488        format.render_response(&resp, &mut values);
489
490        let render = |fmt: &mut fmt::Formatter<'_>| format.render(fmt, &values, 1024, now);
491        let s = format!("{}", FormatDisplay(&render));
492        assert!(s.contains("/test/route/yeah"));
493    }
494
495    #[crate::rt_test]
496    async fn test_percent_format() {
497        let format = Format::new("100%% %U");
498        let req = TestRequest::default().uri("/test").to_srv_request();
499
500        let now = time::SystemTime::now();
501        let values = format.render_request(now, &req);
502
503        let render = |fmt: &mut fmt::Formatter<'_>| format.render(fmt, &values, 1024, now);
504        let s = format!("{}", FormatDisplay(&render));
505        assert_eq!(s, "100% /test");
506    }
507
508    #[crate::rt_test]
509    async fn test_default_format() {
510        let format = Format::default();
511
512        let req =
513            TestRequest::with_header(header::USER_AGENT, header::HeaderValue::from_static("NTEX"))
514                .to_srv_request();
515
516        let now = time::SystemTime::now();
517        let mut values = format.render_request(now, &req);
518
519        let resp = HttpResponse::builder(StatusCode::OK).force_close().build();
520        format.render_response(&resp, &mut values);
521
522        let entry_time = time::SystemTime::now();
523        let render = |fmt: &mut fmt::Formatter<'_>| format.render(fmt, &values, 1024, entry_time);
524        let s = format!("{}", FormatDisplay(&render));
525        assert!(s.contains("GET / HTTP/1.1"));
526        assert!(s.contains("200 1024"));
527        assert!(s.contains("NTEX"));
528    }
529
530    #[crate::rt_test]
531    async fn test_request_time_format() {
532        let format = Format::new("%t");
533        let req = TestRequest::default().to_srv_request();
534
535        let now = time::SystemTime::now();
536        let mut values = format.render_request(now, &req);
537
538        let resp = HttpResponse::builder(StatusCode::OK).force_close().build();
539        format.render_response(&resp, &mut values);
540
541        let render = |fmt: &mut fmt::Formatter<'_>| format.render(fmt, &values, 1024, now);
542        let s = format!("{}", FormatDisplay(&render));
543        assert!(s.contains(&httpdate::HttpDate::from(now).to_string()));
544    }
545
546    #[crate::rt_test]
547    async fn test_missing_values() {
548        let format = Format::new("%{NTEX_LOGGER_MISSING_VAR}e %{X-Missing}o %{X-Missing}i %b");
549        let req = TestRequest::default().to_srv_request();
550
551        let now = time::SystemTime::now();
552        let mut values = format.render_request(now, &req);
553        let resp = HttpResponse::builder(StatusCode::OK).build();
554        format.render_response(&resp, &mut values);
555
556        let render = |fmt: &mut fmt::Formatter<'_>| format.render(fmt, &values, 12, now);
557        assert_eq!(format!("{}", FormatDisplay(&render)), "- - - 12");
558    }
559
560    #[crate::rt_test]
561    async fn test_body_size() {
562        let srv = fn_service(async move |req: WebRequest<()>| {
563            Ok::<_, Infallible>(req.into_response(HttpResponse::Ok().body("TEST")))
564        });
565        let logger = Logger::new("%s %b");
566        let srv = Pipeline::new((), Middleware::create(&logger, &(), srv));
567
568        let mut res = srv
569            .call(TestRequest::default().to_srv_request())
570            .await
571            .unwrap();
572        assert_eq!(res.response_mut().body().size(), BodySize::Sized(4));
573        let body = test::read_body(res).await;
574        assert_eq!(body, Bytes::from_static(b"TEST"));
575    }
576}
ntex/web/middleware/logger.rs

ntex/web/middleware/
logger.rs
