1
  2
  3
  4
  5
  6
  7
  8
  9
 10
 11
 12
 13
 14
 15
 16
 17
 18
 19
 20
 21
 22
 23
 24
 25
 26
 27
 28
 29
 30
 31
 32
 33
 34
 35
 36
 37
 38
 39
 40
 41
 42
 43
 44
 45
 46
 47
 48
 49
 50
 51
 52
 53
 54
 55
 56
 57
 58
 59
 60
 61
 62
 63
 64
 65
 66
 67
 68
 69
 70
 71
 72
 73
 74
 75
 76
 77
 78
 79
 80
 81
 82
 83
 84
 85
 86
 87
 88
 89
 90
 91
 92
 93
 94
 95
 96
 97
 98
 99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121

use crate::middleware::{Middleware, Next};
use crate::{Client, Request, Response};

use std::fmt::Arguments;
use std::sync::atomic::{AtomicUsize, Ordering};
use std::time;

static COUNTER: AtomicUsize = AtomicUsize::new(0);

/// Log each request's duration.

#[derive(Debug, Default)]
pub struct Logger {
    _priv: (),
}

impl Logger {
    /// Create a new instance.

    pub fn new() -> Self {
        Logger { _priv: () }
    }
}

#[async_trait::async_trait]
impl Middleware for Logger {
    #[allow(missing_doc_code_examples)]
    async fn handle(
        &self,
        req: Request,
        client: Client,
        next: Next<'_>,
    ) -> Result<Response, http_types::Error> {
        let start_time = time::Instant::now();
        let uri = format!("{}", req.url());
        let method = format!("{}", req.method());
        let id = COUNTER.fetch_add(1, Ordering::Relaxed);
        print(
            log::Level::Info,
            format_args!("sending request"),
            RequestPairs {
                id,
                uri: &uri,
                method: &method,
            },
        );

        let res = next.run(req, client).await?;

        let status = res.status();
        let elapsed = start_time.elapsed();
        let level = if status.is_server_error() {
            log::Level::Error
        } else if status.is_client_error() {
            log::Level::Warn
        } else {
            log::Level::Info
        };

        print(
            level,
            format_args!("request completed"),
            ResponsePairs {
                id,
                elapsed: &format!("{:?}", elapsed),
                status: status.into(),
            },
        );

        Ok(res)
    }
}

struct RequestPairs<'a> {
    id: usize,
    method: &'a str,
    uri: &'a str,
}
impl<'a> log::kv::Source for RequestPairs<'a> {
    fn visit<'kvs>(
        &'kvs self,
        visitor: &mut dyn log::kv::Visitor<'kvs>,
    ) -> Result<(), log::kv::Error> {
        visitor.visit_pair("req.id".into(), self.id.into())?;
        visitor.visit_pair("req.method".into(), self.method.into())?;
        visitor.visit_pair("req.uri".into(), self.uri.into())?;
        Ok(())
    }
}

struct ResponsePairs<'a> {
    id: usize,
    status: u16,
    elapsed: &'a str,
}

impl<'a> log::kv::Source for ResponsePairs<'a> {
    fn visit<'kvs>(
        &'kvs self,
        visitor: &mut dyn log::kv::Visitor<'kvs>,
    ) -> Result<(), log::kv::Error> {
        visitor.visit_pair("req.id".into(), self.id.into())?;
        visitor.visit_pair("req.status".into(), self.status.into())?;
        visitor.visit_pair("elapsed".into(), self.elapsed.into())?;
        Ok(())
    }
}

fn print(level: log::Level, msg: Arguments<'_>, key_values: impl log::kv::Source) {
    if level <= log::STATIC_MAX_LEVEL && level <= log::max_level() {
        log::logger().log(
            &log::Record::builder()
                .args(msg)
                .key_values(&key_values)
                .level(level)
                .target(module_path!())
                .module_path(Some(module_path!()))
                .file(Some(file!()))
                .line(Some(line!()))
                .build(),
        );
    }
}