road-runner-common 0.12.1

#![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_ID_HEADER};

/// Request log middleware (structured).
///
/// Opens an `http_request` span per request (bound with `Instrument`, never
/// `Span::enter`, so concurrent requests cannot nest into each other) and emits
/// one completion event whose level follows the response status: 5xx → ERROR,
/// 4xx → WARN, otherwise INFO. `user.id` is recorded onto the span once the
/// identity is resolved downstream.
///
/// 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")]
        {
            use tracing::Instrument;

            let log_successful_probes = self.log_successful_probes;
            let start = Instant::now();

            let method = req.method().to_string();
            let path = req.path().to_string();
            let client_ip = req
                .connection_info()
                .realip_remote_addr()
                .map(|s| s.to_string())
                .unwrap_or_else(|| "-".into());

            // RequestIdMiddleware runs outermost and provides the extension; the
            // header/generate fallbacks keep the id meaningful even when this
            // middleware is wired ahead of it (or without it). A generated id is
            // inserted back so downstream sees the same value.
            let known_id = req.extensions().get::<RequestId>().map(|r| r.0.clone());
            let known_id = known_id.or_else(|| {
                req.headers()
                    .get(REQUEST_ID_HEADER)
                    .and_then(|v| v.to_str().ok())
                    .map(|s| s.to_string())
                    .filter(|s| !s.trim().is_empty())
            });
            let request_id = known_id.unwrap_or_else(|| {
                let generated = uuid::Uuid::new_v4().to_string();
                req.extensions_mut().insert(RequestId(generated.clone()));
                generated
            });

            let span = tracing::info_span!(
                "http_request",
                request_id = %request_id,
                http.method = tracing::field::Empty,
                http.path = %path,
                client.ip = %client_ip,
                user.id = tracing::field::Empty,
            );

            // Pretty output already carries the method keyless in the
            // completion message; only structured output needs it as a field.
            if !crate::observability::is_pretty_format() {
                span.record("http.method", tracing::field::display(&method));
            }

            return Box::pin(
                async move {
                    let result = srv.call(req).await;
                    let elapsed_ms = start.elapsed().as_millis() as u64;

                    match result {
                        Ok(res) => {
                            if let Some(ctx) = res.request().extensions().get::<UserContext>() {
                                tracing::Span::current()
                                    .record("user.id", tracing::field::display(&ctx.subject));
                            }

                            let status = res.status().as_u16();
                            if should_log_completed_request(&path, status, log_successful_probes) {
                                if crate::observability::is_pretty_format() {
                                    // Human-readable completion line; the rest of
                                    // the request context follows from the span
                                    // fields at the end of the line.
                                    if status >= 500 {
                                        tracing::error!(
                                            "request completed {status} {elapsed_ms}ms {method}"
                                        );
                                    } else if status >= 400 {
                                        tracing::warn!(
                                            "request completed {status} {elapsed_ms}ms {method}"
                                        );
                                    } else {
                                        tracing::info!(
                                            "request completed {status} {elapsed_ms}ms {method}"
                                        );
                                    }
                                } else if status >= 500 {
                                    tracing::error!(
                                        http.status_code = status,
                                        duration_ms = elapsed_ms,
                                        "request completed"
                                    );
                                } else if status >= 400 {
                                    tracing::warn!(
                                        http.status_code = status,
                                        duration_ms = elapsed_ms,
                                        "request completed"
                                    );
                                } else {
                                    tracing::info!(
                                        http.status_code = status,
                                        duration_ms = elapsed_ms,
                                        "request completed"
                                    );
                                }
                            }

                            Ok(res)
                        }
                        Err(err) => {
                            if crate::observability::is_pretty_format() {
                                tracing::error!(
                                    error = %err,
                                    "request failed {elapsed_ms}ms {method}"
                                );
                            } else {
                                tracing::error!(
                                    duration_ms = elapsed_ms,
                                    error = %err,
                                    "request failed"
                                );
                            }

                            Err(err)
                        }
                    }
                }
                .instrument(span),
            );
        }

        #[cfg(not(feature = "observability"))]
        {
            let _ = self.log_successful_probes;
            Box::pin(async move { srv.call(req).await })
        }
    }
}

#[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));
    }
}