Skip to content

Commit

Permalink
feat: [torrust#1146] override tower-http tracing error
Browse files Browse the repository at this point in the history
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.
  • Loading branch information
josecelano committed Dec 23, 2024
1 parent 90f6a01 commit 9ac676c
Show file tree
Hide file tree
Showing 4 changed files with 62 additions and 3 deletions.
12 changes: 11 additions & 1 deletion src/servers/apis/routes.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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)]
Expand Down Expand Up @@ -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(
Expand Down
12 changes: 11 additions & 1 deletion src/servers/health_check_api/server.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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};

Expand Down Expand Up @@ -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));

Expand Down
12 changes: 11 additions & 1 deletion src/servers/http/v1/routes.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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.
///
Expand Down Expand Up @@ -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(
Expand Down
29 changes: 29 additions & 0 deletions src/servers/logging.rs
Original file line number Diff line number Diff line change
@@ -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:
Expand Down Expand Up @@ -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"),
}
}
}

0 comments on commit 9ac676c

Please sign in to comment.