road-runner-common 0.11.0

#![cfg(feature = "web")]

use actix_service::{forward_ready, Service, Transform};
#[cfg(feature = "observability")]
use actix_web::HttpMessage;
use actix_web::{
    dev::{ServiceRequest, ServiceResponse},
    Error,
};
use futures_util::future::{ready, LocalBoxFuture, Ready};
use std::rc::Rc;
#[cfg(feature = "observability")]
use std::time::Instant;

#[cfg(feature = "observability")]
use crate::auth::UserContext;
#[cfg(feature = "observability")]
use crate::middleware::RequestId;

/// Request log middleware (structured).
///
/// Successful `/healthz` and `/readyz` requests are omitted by default to keep
/// probe traffic out of application logs. Services that need those events can
/// opt in with [`RequestLogMiddleware::with_successful_probe_logging`]. Probe
/// responses with any status other than 200 are always logged.
///
/// ```ignore
/// .wrap(RequestLogMiddleware::with_successful_probe_logging(true))
/// ```
pub struct RequestLogMiddleware;

impl RequestLogMiddleware {
    pub const fn with_successful_probe_logging(enabled: bool) -> ConfiguredRequestLogMiddleware {
        ConfiguredRequestLogMiddleware {
            log_successful_probes: enabled,
        }
    }
}

/// Configured variant returned by
/// [`RequestLogMiddleware::with_successful_probe_logging`].
pub struct ConfiguredRequestLogMiddleware {
    log_successful_probes: bool,
}

impl<S, B> Transform<S, ServiceRequest> for RequestLogMiddleware
where
    S: Service<ServiceRequest, Response = ServiceResponse<B>, Error = Error> + 'static,
    B: 'static,
{
    type Response = ServiceResponse<B>;
    type Error = Error;
    type InitError = ();
    type Transform = RequestLogMiddlewareService<S>;
    type Future = Ready<Result<Self::Transform, Self::InitError>>;

    fn new_transform(&self, service: S) -> Self::Future {
        ready(Ok(RequestLogMiddlewareService {
            service: Rc::new(service),
            log_successful_probes: false,
        }))
    }
}

impl<S, B> Transform<S, ServiceRequest> for ConfiguredRequestLogMiddleware
where
    S: Service<ServiceRequest, Response = ServiceResponse<B>, Error = Error> + 'static,
    B: 'static,
{
    type Response = ServiceResponse<B>;
    type Error = Error;
    type InitError = ();
    type Transform = RequestLogMiddlewareService<S>;
    type Future = Ready<Result<Self::Transform, Self::InitError>>;

    fn new_transform(&self, service: S) -> Self::Future {
        ready(Ok(RequestLogMiddlewareService {
            service: Rc::new(service),
            log_successful_probes: self.log_successful_probes,
        }))
    }
}

pub struct RequestLogMiddlewareService<S> {
    service: Rc<S>,
    log_successful_probes: bool,
}

impl<S, B> Service<ServiceRequest> for RequestLogMiddlewareService<S>
where
    S: Service<ServiceRequest, Response = ServiceResponse<B>, Error = Error> + 'static,
    B: 'static,
{
    type Response = ServiceResponse<B>;
    type Error = Error;
    type Future = LocalBoxFuture<'static, Result<Self::Response, Self::Error>>;

    forward_ready!(service);

    fn call(&self, req: ServiceRequest) -> Self::Future {
        let srv = self.service.clone();
        #[cfg(feature = "observability")]
        let log_successful_probes = self.log_successful_probes;
        #[cfg(not(feature = "observability"))]
        let _log_successful_probes = self.log_successful_probes;
        #[cfg(feature = "observability")]
        let start = Instant::now();

        // request metadata
        #[cfg(feature = "observability")]
        let method = req.method().to_string();
        #[cfg(feature = "observability")]
        let path = req.path().to_string();
        #[cfg(feature = "observability")]
        let peer = req
            .connection_info()
            .realip_remote_addr()
            .map(|s| s.to_string());

        #[cfg(feature = "observability")]
        let rid = req
            .extensions()
            .get::<RequestId>()
            .map(|r| r.0.clone())
            .unwrap_or_else(|| "missing".to_string());

        #[cfg(feature = "observability")]
        let user_id = req
            .extensions()
            .get::<UserContext>()
            .map(|ctx| ctx.subject.clone());

        Box::pin(async move {
            #[cfg(feature = "observability")]
            let span = tracing::info_span!(
                "http_request",
                request_id = %rid,
                http.method = %method,
                http.path = %path,
                user.id = %user_id.clone().unwrap_or_else(|| "-".into()),
                client.ip = %peer.clone().unwrap_or_else(|| "-".into()),
            );

            #[cfg(feature = "observability")]
            let _enter = span.enter();

            let result = srv.call(req).await;

            #[cfg(feature = "observability")]
            let elapsed_ms = start.elapsed().as_millis() as u64;

            match result {
                Ok(res) => {
                    #[cfg(feature = "observability")]
                    {
                        let status = res.status().as_u16();
                        if should_log_completed_request(&path, status, log_successful_probes) {
                            tracing::info!(
                                http.status_code = status,
                                duration_ms = elapsed_ms,
                                "request completed"
                            );
                        }
                    }

                    Ok(res)
                }
                Err(err) => {
                    #[cfg(feature = "observability")]
                    tracing::error!(
                        duration_ms = elapsed_ms,
                        error = %err,
                        "request failed"
                    );

                    Err(err)
                }
            }
        })
    }
}

#[cfg(any(feature = "observability", test))]
fn should_log_completed_request(path: &str, status: u16, log_successful_probes: bool) -> bool {
    log_successful_probes
        || status != actix_web::http::StatusCode::OK.as_u16()
        || !matches!(path, "/healthz" | "/readyz")
}

#[cfg(test)]
mod tests {
    use super::should_log_completed_request;

    #[test]
    fn successful_probes_are_suppressed_by_default() {
        assert!(!should_log_completed_request("/healthz", 200, false));
        assert!(!should_log_completed_request("/readyz", 200, false));
    }

    #[test]
    fn unsuccessful_probes_are_always_logged() {
        assert!(should_log_completed_request("/healthz", 503, false));
        assert!(should_log_completed_request("/readyz", 500, false));
    }

    #[test]
    fn successful_probe_logging_can_be_enabled() {
        assert!(should_log_completed_request("/healthz", 200, true));
        assert!(should_log_completed_request("/readyz", 200, true));
    }

    #[test]
    fn non_probe_requests_are_always_logged() {
        assert!(should_log_completed_request("/api/orders", 200, false));
        assert!(should_log_completed_request("/healthz/", 200, false));
    }
}