Merge #1151: Override tower-http tracing errors

9ac676c feat: [#1146] override tower-http tracing error (Jose Celano)

Pull request description:

  This overrides the default log errors when a 500 response is sent to the client.

  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 for the inserting of more fields in the future, for example, to write assertions about logs.

ACKs for top commit:
  josecelano:
    ACK 9ac676c

Tree-SHA512: 4e2eb9057ea15bf28f2a5ab6a8d8becc072520d428fe6718ea2275a7ccd028e21d9907fb7d9626b8beba80ccfd72a60c040bdae902c1ec4b41fa31a8e8014974

Author: josecelano

src/servers/apis/routes.rs

@@ -17,17 +17,20 @@ 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;
 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<Tracker>, access_tokens: Arc<AccessTokens>) -> 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(

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));
 

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<Tracker>, 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(

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"),
+        }
+    }
+}