Merge torrust#485: Overhaul logging

1e96237 ci: fix missing tools in coverage workflow (Jose Celano)
2eaeba8 fix: [torrust#468] mising request ID when not provided by client (Jose Celano)
a206737 feat: [torrust#468] add custom request log (Jose Celano)
91f818e feat: [torrust#468] add request id to response log (Jose Celano)
db6a62f chore: [torrust#468] set and propagate request ID (Jose Celano)
3ec28ba chore: [torrust#468] add new features to propagate ID in requests (Jose Celano)
e5ebcc0 feat: [torrust#468] deafult logging for API requests (Jose Celano)
c1e01f8 chore: [torrust#468] add cargo dependencies for tracing (Jose Celano)
bc003e4 feat: [torrust#468] improve tracker stats importer logs (Jose Celano)

Pull request description:

  Overhaul logging.

  - [x] Improve tracker stats importer logs.
  - [x] Improve tracker API logs.
     - [x] Enable default logging for Axum API requests.
     - [x] Link requests and responses with an ID.
     - [x] Add target `API` to the log lines.

ACKs for top commit:
  josecelano:
    ACK 1e96237

Tree-SHA512: e315cb3c1862853331d07417b41762978ad28c97b5b45cdafc8e2da134fd73eb633d3fd04d868e264c35f7e874792b8e4c4e457decf579b412b9733bb9b4e261

.github/workflows/coverage.yaml

@@ -54,7 +54,7 @@ jobs:
         name: Install Tools
         uses: taiki-e/install-action@v2
         with:
-          tool: grcov
+          tool: cargo-llvm-cov, cargo-nextest, grcov
 
       - id: imdl
         name: Install Intermodal

Cargo.toml

@@ -74,7 +74,9 @@ thiserror = "1"
 tokio = { version = "1", features = ["fs", "io-util", "macros", "net", "rt-multi-thread", "signal", "sync", "time"] }
 toml = "0"
 torrust-index-located-error = { version = "3.0.0-alpha.3-develop", path = "packages/located-error" }
-tower-http = { version = "0", features = ["compression-full", "cors"] }
+tower-http = { version = "0", features = ["compression-full", "cors", "trace", "propagate-header", "request-id"] }
+trace = "0.1.7"
+tracing = "0.1.40"
 urlencoding = "2"
 uuid = { version = "1", features = ["v4"] }
 

src/tracker/statistics_importer.rs

@@ -1,11 +1,15 @@
 use std::sync::Arc;
+use std::time::Instant;
 
 use log::{error, info};
+use text_colorizer::Colorize;
 
 use super::service::{Service, TorrentInfo, TrackerAPIError};
 use crate::config::Configuration;
 use crate::databases::database::{self, Database};
 
+const LOG_TARGET: &str = "Tracker Stats Importer";
+
 pub struct StatisticsImporter {
     database: Arc<Box<dyn Database>>,
     tracker_service: Arc<Service>,
@@ -30,11 +34,15 @@ impl StatisticsImporter {
     ///
     /// Will return an error if the database query failed.
     pub async fn import_all_torrents_statistics(&self) -> Result<(), database::Error> {
-        info!("Importing torrents statistics from tracker ...");
         let torrents = self.database.get_all_torrents_compact().await?;
 
+        info!(target: LOG_TARGET, "Importing {} torrents statistics from tracker {} ...", torrents.len().to_string().yellow(), self.tracker_url.yellow());
+
+        // Start the timer before the loop
+        let start_time = Instant::now();
+
         for torrent in torrents {
-            info!("Updating torrent {} ...", torrent.torrent_id);
+            info!(target: LOG_TARGET, "Importing torrent #{} ...", torrent.torrent_id.to_string().yellow());
 
             let ret = self.import_torrent_statistics(torrent.torrent_id, &torrent.info_hash).await;
 
@@ -49,6 +57,10 @@ impl StatisticsImporter {
             }
         }
 
+        let elapsed_time = start_time.elapsed();
+
+        info!(target: LOG_TARGET, "Statistics import completed in {:.2?}", elapsed_time);
+
         Ok(())
     }
 

src/web/api/server/v1/routes.rs

@@ -1,14 +1,22 @@
 //! Route initialization for the v1 API.
 use std::env;
 use std::sync::Arc;
+use std::time::Duration;
 
 use axum::extract::DefaultBodyLimit;
-use axum::response::Redirect;
+use axum::http::{HeaderName, HeaderValue};
+use axum::response::{Redirect, Response};
 use axum::routing::get;
 use axum::{Json, Router};
+use hyper::Request;
 use serde_json::{json, Value};
 use tower_http::compression::CompressionLayer;
 use tower_http::cors::CorsLayer;
+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::contexts::{about, category, proxy, settings, tag, torrent, user};
 use crate::bootstrap::config::ENV_VAR_CORS_PERMISSIVE;
@@ -37,7 +45,7 @@ pub fn router(app_data: Arc<AppData>) -> Router {
 
     let router = Router::new()
         .route("/", get(redirect_to_about))
-        .route("/health_check", get(health_check_handler).with_state(app_data))
+        .route("/health_check", get(health_check_handler).with_state(app_data.clone()))
         .nest(&format!("/{API_VERSION_URL_PREFIX}"), v1_api_routes);
 
     let router = if env::var(ENV_VAR_CORS_PERMISSIVE).is_ok() {
@@ -46,7 +54,42 @@ pub fn router(app_data: Arc<AppData>) -> Router {
         router
     };
 
-    router.layer(DefaultBodyLimit::max(10_485_760)).layer(CompressionLayer::new())
+    router
+        .layer(DefaultBodyLimit::max(10_485_760))
+        .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<axum::body::Body>, _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: "API",
+                        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: "API",
+                        tracing::Level::INFO, "response", latency = %latency_ms, status = %status_code, request_id = %request_id);
+                }),
+        )
+        .layer(SetRequestIdLayer::x_request_id(RequestIdGenerator))
 }
 
 /// Endpoint for container health check.
@@ -57,3 +100,13 @@ async fn health_check_handler() -> Json<Value> {
 async fn redirect_to_about() -> Redirect {
     Redirect::permanent(&format!("/{API_VERSION_URL_PREFIX}/about"))
 }
+
+#[derive(Clone, Default)]
+struct RequestIdGenerator;
+
+impl MakeRequestId for RequestIdGenerator {
+    fn make_request_id<B>(&mut self, _request: &Request<B>) -> Option<RequestId> {
+        let id = HeaderValue::from_str(&Uuid::new_v4().to_string()).expect("UUID is a valid HTTP header value");
+        Some(RequestId::new(id))
+    }
+}