From 8e25d43e135928a5490c4d0d802ddfaa1176880f Mon Sep 17 00:00:00 2001 From: Jose Celano Date: Mon, 19 Feb 2024 13:01:19 +0000 Subject: [PATCH] feat: [#697] add logs to HTTP tracker Sample logs: ``` 2024-02-19T13:00:12.631712627+00:00 [HTTP TRACKER][INFO] request; method=GET uri=/health_check request_id=24a3f4a2-99e5-4db1-890f-f7196a294c2a 2024-02-19T13:00:12.631765246+00:00 [HTTP TRACKER][INFO] response; latency=0 status=200 OK request_id=24a3f4a2-99e5-4db1-890f-f7196a294c2a ``` --- src/console/ci/e2e/logs_parser.rs | 8 ++--- src/servers/http/server.rs | 4 +-- src/servers/http/v1/routes.rs | 52 +++++++++++++++++++++++++++++++ 3 files changed, 58 insertions(+), 6 deletions(-) diff --git a/src/console/ci/e2e/logs_parser.rs b/src/console/ci/e2e/logs_parser.rs index 82e37f7d7..ca4d6099c 100644 --- a/src/console/ci/e2e/logs_parser.rs +++ b/src/console/ci/e2e/logs_parser.rs @@ -2,7 +2,7 @@ use serde::{Deserialize, Serialize}; const UDP_TRACKER_PATTERN: &str = "[UDP Tracker][INFO] Starting on: udp://"; -const HTTP_TRACKER_PATTERN: &str = "[HTTP Tracker][INFO] Starting on: "; +const HTTP_TRACKER_PATTERN: &str = "[HTTP TRACKER][INFO] Starting on: "; const HEALTH_CHECK_PATTERN: &str = "[HEALTH CHECK API][INFO] Starting on: "; #[derive(Serialize, Deserialize, Debug, Default)] @@ -22,8 +22,8 @@ impl RunningServices { /// 2024-01-24T16:36:14.614898789+00:00 [torrust_tracker::bootstrap::logging][INFO] logging initialized. /// 2024-01-24T16:36:14.615586025+00:00 [UDP Tracker][INFO] Starting on: udp://0.0.0.0:6969 /// 2024-01-24T16:36:14.615623705+00:00 [torrust_tracker::bootstrap::jobs][INFO] TLS not enabled - /// 2024-01-24T16:36:14.615694484+00:00 [HTTP Tracker][INFO] Starting on: http://0.0.0.0:7070 - /// 2024-01-24T16:36:14.615710534+00:00 [HTTP Tracker][INFO] Started on: http://0.0.0.0:7070 + /// 2024-01-24T16:36:14.615694484+00:00 [HTTP TRACKER][INFO] Starting on: http://0.0.0.0:7070 + /// 2024-01-24T16:36:14.615710534+00:00 [HTTP TRACKER][INFO] Started on: http://0.0.0.0:7070 /// 2024-01-24T16:36:14.615716574+00:00 [torrust_tracker::bootstrap::jobs][INFO] TLS not enabled /// 2024-01-24T16:36:14.615764904+00:00 [API][INFO] Starting on http://127.0.0.1:1212 /// 2024-01-24T16:36:14.615767264+00:00 [API][INFO] Started on http://127.0.0.1:1212 @@ -87,7 +87,7 @@ mod tests { fn it_should_parse_from_logs_with_valid_logs() { let logs = "\ [UDP Tracker][INFO] Starting on: udp://0.0.0.0:8080\n\ - [HTTP Tracker][INFO] Starting on: 0.0.0.0:9090\n\ + [HTTP TRACKER][INFO] Starting on: 0.0.0.0:9090\n\ [HEALTH CHECK API][INFO] Starting on: 0.0.0.0:10010"; let running_services = RunningServices::parse_from_logs(logs); diff --git a/src/servers/http/server.rs b/src/servers/http/server.rs index 20e57db57..a054d2a23 100644 --- a/src/servers/http/server.rs +++ b/src/servers/http/server.rs @@ -55,7 +55,7 @@ impl Launcher { let tls = self.tls.clone(); let protocol = if tls.is_some() { "https" } else { "http" }; - info!(target: "HTTP Tracker", "Starting on: {protocol}://{}", address); + info!(target: "HTTP TRACKER", "Starting on: {protocol}://{}", address); let running = Box::pin(async { match tls { @@ -72,7 +72,7 @@ impl Launcher { } }); - info!(target: "HTTP Tracker", "Started on: {protocol}://{}", address); + info!(target: "HTTP TRACKER", "Started on: {protocol}://{}", address); tx_start .send(Started { address }) diff --git a/src/servers/http/v1/routes.rs b/src/servers/http/v1/routes.rs index 20e96d7fd..092d4624d 100644 --- a/src/servers/http/v1/routes.rs +++ b/src/servers/http/v1/routes.rs @@ -1,10 +1,19 @@ //! HTTP server routes for version `v1`. use std::sync::Arc; +use std::time::Duration; +use axum::http::{HeaderName, HeaderValue}; +use axum::response::Response; use axum::routing::get; use axum::Router; use axum_client_ip::SecureClientIpSource; +use hyper::Request; use tower_http::compression::CompressionLayer; +use tower_http::propagate_header::PropagateHeaderLayer; +use tower_http::request_id::{MakeRequestId, RequestId, SetRequestIdLayer}; +use tower_http::trace::{DefaultMakeSpan, TraceLayer}; +use tracing::{Level, Span}; +use uuid::Uuid; use super::handlers::{announce, health_check, scrape}; use crate::core::Tracker; @@ -27,4 +36,47 @@ pub fn router(tracker: Arc) -> Router { // Add extension to get the client IP from the connection info .layer(SecureClientIpSource::ConnectInfo.into_extension()) .layer(CompressionLayer::new()) + .layer(SetRequestIdLayer::x_request_id(RequestIdGenerator)) + .layer(PropagateHeaderLayer::new(HeaderName::from_static("x-request-id"))) + .layer( + TraceLayer::new_for_http() + .make_span_with(DefaultMakeSpan::new().level(Level::INFO)) + .on_request(|request: &Request, _span: &Span| { + let method = request.method().to_string(); + let uri = request.uri().to_string(); + let request_id = request + .headers() + .get("x-request-id") + .map(|v| v.to_str().unwrap_or_default()) + .unwrap_or_default(); + + tracing::span!( + target: "HTTP TRACKER", + tracing::Level::INFO, "request", method = %method, uri = %uri, request_id = %request_id); + }) + .on_response(|response: &Response, latency: Duration, _span: &Span| { + let status_code = response.status(); + let request_id = response + .headers() + .get("x-request-id") + .map(|v| v.to_str().unwrap_or_default()) + .unwrap_or_default(); + let latency_ms = latency.as_millis(); + + tracing::span!( + target: "HTTP TRACKER", + tracing::Level::INFO, "response", latency = %latency_ms, status = %status_code, request_id = %request_id); + }), + ) + .layer(SetRequestIdLayer::x_request_id(RequestIdGenerator)) +} + +#[derive(Clone, Default)] +struct RequestIdGenerator; + +impl MakeRequestId for RequestIdGenerator { + fn make_request_id(&mut self, _request: &Request) -> Option { + let id = HeaderValue::from_str(&Uuid::new_v4().to_string()).expect("UUID is a valid HTTP header value"); + Some(RequestId::new(id)) + } }