From 9ac676c714ccf94feb6ece5a8e7cfc23d0650104 Mon Sep 17 00:00:00 2001 From: Jose Celano Date: Mon, 23 Dec 2024 16:08:12 +0000 Subject: [PATCH] feat: [#1146] override tower-http tracing error From: ``` 2024-12-23T15:54:25.842837Z ERROR tower_http::trace::on_failure: response failed classification=Status code: 500 Internal Server Error latency=0 ms ``` To: ``` 2024-12-23T16:06:53.553023Z ERROR API: response failed classification=Status code: 500 Internal Server Error latency=0 ms ``` The target has been changed: ``` 2024-12-23T15:54:25.842837Z ERROR tower_http::trace::on_failure: response failed classification=Status code: 500 Internal Server Error latency=0 ms 2024-12-23T16:06:53.553023Z ERROR API: response failed classification=Status code: 500 Internal Server Error latency=0 ms ``` It was changed to: - Easily identify the origin of the error in our code. - Allow to insert more fields in the future, for example, to write assertions about logs. --- src/servers/apis/routes.rs | 12 ++++++++++- src/servers/health_check_api/server.rs | 12 ++++++++++- src/servers/http/v1/routes.rs | 12 ++++++++++- src/servers/logging.rs | 29 ++++++++++++++++++++++++++ 4 files changed, 62 insertions(+), 3 deletions(-) diff --git a/src/servers/apis/routes.rs b/src/servers/apis/routes.rs index 327cab0c5..2ae422607 100644 --- a/src/servers/apis/routes.rs +++ b/src/servers/apis/routes.rs @@ -17,10 +17,12 @@ use hyper::{Request, StatusCode}; use torrust_tracker_configuration::{AccessTokens, DEFAULT_TIMEOUT}; use tower::timeout::TimeoutLayer; use tower::ServiceBuilder; +use tower_http::classify::ServerErrorsFailureClass; use tower_http::compression::CompressionLayer; use tower_http::propagate_header::PropagateHeaderLayer; use tower_http::request_id::{MakeRequestUuid, SetRequestIdLayer}; use tower_http::trace::{DefaultMakeSpan, TraceLayer}; +use tower_http::LatencyUnit; use tracing::{instrument, Level, Span}; use super::v1; @@ -28,6 +30,7 @@ use super::v1::context::health_check::handlers::health_check_handler; use super::v1::middlewares::auth::State; use crate::core::Tracker; use crate::servers::apis::API_LOG_TARGET; +use crate::servers::logging::Latency; /// Add all API routes to the router. #[allow(clippy::needless_pass_by_value)] @@ -75,7 +78,14 @@ pub fn router(tracker: Arc, access_tokens: Arc) -> Router tracing::span!( target: API_LOG_TARGET, tracing::Level::INFO, "response", latency = %latency_ms, status = %status_code, request_id = %request_id); - }), + }) + .on_failure(|failure_classification: ServerErrorsFailureClass, latency: Duration, _span: &Span| { + let latency = Latency::new( + LatencyUnit::Millis, + latency, + ); + tracing::error!(target: API_LOG_TARGET, "response failed classification={failure_classification} latency={latency}"); + }) ) .layer(SetRequestIdLayer::x_request_id(MakeRequestUuid)) .layer( diff --git a/src/servers/health_check_api/server.rs b/src/servers/health_check_api/server.rs index df4b1cf69..f8ca65b82 100644 --- a/src/servers/health_check_api/server.rs +++ b/src/servers/health_check_api/server.rs @@ -14,15 +14,18 @@ use futures::Future; use hyper::Request; use serde_json::json; use tokio::sync::oneshot::{Receiver, Sender}; +use tower_http::classify::ServerErrorsFailureClass; use tower_http::compression::CompressionLayer; use tower_http::propagate_header::PropagateHeaderLayer; use tower_http::request_id::{MakeRequestUuid, SetRequestIdLayer}; use tower_http::trace::{DefaultMakeSpan, TraceLayer}; +use tower_http::LatencyUnit; use tracing::{instrument, Level, Span}; use crate::bootstrap::jobs::Started; use crate::servers::health_check_api::handlers::health_check_handler; use crate::servers::health_check_api::HEALTH_CHECK_API_LOG_TARGET; +use crate::servers::logging::Latency; use crate::servers::registar::ServiceRegistry; use crate::servers::signals::{graceful_shutdown, Halted}; @@ -73,7 +76,14 @@ pub fn start( tracing::span!( target: HEALTH_CHECK_API_LOG_TARGET, tracing::Level::INFO, "response", latency = %latency_ms, status = %status_code, request_id = %request_id); - }), + }) + .on_failure(|failure_classification: ServerErrorsFailureClass, latency: Duration, _span: &Span| { + let latency = Latency::new( + LatencyUnit::Millis, + latency, + ); + tracing::error!(target: HEALTH_CHECK_API_LOG_TARGET, "response failed classification={failure_classification} latency={latency}"); + }) ) .layer(SetRequestIdLayer::x_request_id(MakeRequestUuid)); diff --git a/src/servers/http/v1/routes.rs b/src/servers/http/v1/routes.rs index 16e39b61b..6eacb1e5c 100644 --- a/src/servers/http/v1/routes.rs +++ b/src/servers/http/v1/routes.rs @@ -13,15 +13,18 @@ use hyper::{Request, StatusCode}; use torrust_tracker_configuration::DEFAULT_TIMEOUT; use tower::timeout::TimeoutLayer; use tower::ServiceBuilder; +use tower_http::classify::ServerErrorsFailureClass; use tower_http::compression::CompressionLayer; use tower_http::propagate_header::PropagateHeaderLayer; use tower_http::request_id::{MakeRequestUuid, SetRequestIdLayer}; use tower_http::trace::{DefaultMakeSpan, TraceLayer}; +use tower_http::LatencyUnit; use tracing::{instrument, Level, Span}; use super::handlers::{announce, health_check, scrape}; use crate::core::Tracker; use crate::servers::http::HTTP_TRACKER_LOG_TARGET; +use crate::servers::logging::Latency; /// It adds the routes to the router. /// @@ -72,7 +75,14 @@ pub fn router(tracker: Arc, server_socket_addr: SocketAddr) -> Router { tracing::span!( target: HTTP_TRACKER_LOG_TARGET, tracing::Level::INFO, "response", server_socket_addr= %server_socket_addr, latency = %latency_ms, status = %status_code, request_id = %request_id); - }), + }) + .on_failure(|failure_classification: ServerErrorsFailureClass, latency: Duration, _span: &Span| { + let latency = Latency::new( + LatencyUnit::Millis, + latency, + ); + tracing::error!(target: HTTP_TRACKER_LOG_TARGET, "response failed classification={failure_classification} latency={latency}"); + }) ) .layer(SetRequestIdLayer::x_request_id(MakeRequestUuid)) .layer( diff --git a/src/servers/logging.rs b/src/servers/logging.rs index ad9ccbbcc..c503cfd35 100644 --- a/src/servers/logging.rs +++ b/src/servers/logging.rs @@ -1,3 +1,8 @@ +use std::fmt; +use std::time::Duration; + +use tower_http::LatencyUnit; + /// This is the prefix used in logs to identify a started service. /// /// For example: @@ -27,3 +32,27 @@ We should use something like: ``` */ + +pub struct Latency { + unit: LatencyUnit, + duration: Duration, +} + +impl Latency { + #[must_use] + pub fn new(unit: LatencyUnit, duration: Duration) -> Self { + Self { unit, duration } + } +} + +impl fmt::Display for Latency { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + match self.unit { + LatencyUnit::Seconds => write!(f, "{} s", self.duration.as_secs_f64()), + LatencyUnit::Millis => write!(f, "{} ms", self.duration.as_millis()), + LatencyUnit::Micros => write!(f, "{} μs", self.duration.as_micros()), + LatencyUnit::Nanos => write!(f, "{} ns", self.duration.as_nanos()), + _ => panic!("Invalid latency unit"), + } + } +}