feat: [#700] add logs to Health Check API

``````
2024-02-19T11:30:21.061293933+00:00 [HEALTH CHECK API][INFO] request; method=GET uri=/health_check request_id=78933bbf-c4cf-4897-b972-4c0fd252159a
2024-02-19T11:30:21.070329733+00:00 [HEALTH CHECK API][INFO] response; latency=9 status=200 OK request_id=78933bbf-c4cf-4897-b972-4c0fd252159a
```

src/bootstrap/jobs/health_check_api.rs

@@ -47,18 +47,18 @@ pub async fn start_job(config: &HealthCheckApi, register: ServiceRegistry) -> Jo
 
  // Run the API server
  let join_handle = tokio::spawn(async move {
- info!(target: "Health Check API", "Starting on: {protocol}://{}", bind_addr);
+ info!(target: "HEALTH CHECK API", "Starting on: {protocol}://{}", bind_addr);
 
  let handle = server::start(bind_addr, tx_start, rx_halt, register);
 
  if let Ok(()) = handle.await {
- info!(target: "Health Check API", "Stopped server running on: {protocol}://{}", bind_addr);
+ info!(target: "HEALTH CHECK API", "Stopped server running on: {protocol}://{}", bind_addr);
  }
  });
 
  // Wait until the server sends the started message
  match rx_start.await {
- Ok(msg) => info!(target: "Health Check API", "Started on: {protocol}://{}", msg.address),
+ Ok(msg) => info!(target: "HEALTH CHECK API", "Started on: {protocol}://{}", msg.address),
  Err(e) => panic!("the Health Check API server was dropped: {e}"),
  }
 

src/console/ci/e2e/logs_parser.rs

@@ -3,7 +3,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 HEALTH_CHECK_PATTERN: &str = "[Health Check API][INFO] Starting on: ";
+const HEALTH_CHECK_PATTERN: &str = "[HEALTH CHECK API][INFO] Starting on: ";
 
 #[derive(Serialize, Deserialize, Debug, Default)]
 pub struct RunningServices {
@@ -27,8 +27,8 @@ impl RunningServices {
  /// 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
- /// 2024-01-24T16:36:14.615777574+00:00 [Health Check API][INFO] Starting on: http://127.0.0.1:1313
- /// 2024-01-24T16:36:14.615791124+00:00 [Health Check API][INFO] Started on: http://127.0.0.1:1313
+ /// 2024-01-24T16:36:14.615777574+00:00 [HEALTH CHECK API][INFO] Starting on: http://127.0.0.1:1313
+ /// 2024-01-24T16:36:14.615791124+00:00 [HEALTH CHECK API][INFO] Started on: http://127.0.0.1:1313
  /// ```
  ///
  /// It would extract these services:
@@ -88,7 +88,7 @@ mod tests {
  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\
- [Health Check API][INFO] Starting on: 0.0.0.0:10010";
+ [HEALTH CHECK API][INFO] Starting on: 0.0.0.0:10010";
  let running_services = RunningServices::parse_from_logs(logs);
 
  assert_eq!(running_services.udp_trackers, vec!["127.0.0.1:8080"]);

src/servers/health_check_api/server.rs

@@ -3,14 +3,24 @@
 //! This API is intended to be used by the container infrastructure to check if
 //! the whole application is healthy.
 use std::net::SocketAddr;
+use std::time::Duration;
 
+use axum::http::{HeaderName, HeaderValue};
+use axum::response::Response;
 use axum::routing::get;
 use axum::{Json, Router};
 use axum_server::Handle;
 use futures::Future;
+use hyper::Request;
 use log::debug;
 use serde_json::json;
 use tokio::sync::oneshot::{Receiver, Sender};
+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 crate::bootstrap::jobs::Started;
 use crate::servers::health_check_api::handlers::health_check_handler;
@@ -31,14 +41,48 @@ pub fn start(
  let router = Router::new()
  .route("/", get(|| async { Json(json!({})) }))
  .route("/health_check", get(health_check_handler))
- .with_state(register);
+ .with_state(register)
+ .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: "HEALTH CHECK 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: "HEALTH CHECK API",
+ tracing::Level::INFO, "response", latency = %latency_ms, status = %status_code, request_id = %request_id);
+ }),
+ )
+ .layer(SetRequestIdLayer::x_request_id(RequestIdGenerator));
 
  let socket = std::net::TcpListener::bind(bind_to).expect("Could not bind tcp_listener to address.");
  let address = socket.local_addr().expect("Could not get local_addr from tcp_listener.");
 
  let handle = Handle::new();
 
- debug!(target: "Health Check API", "Starting service with graceful shutdown in a spawned task ...");
+ debug!(target: "HEALTH CHECK API", "Starting service with graceful shutdown in a spawned task ...");
 
  tokio::task::spawn(graceful_shutdown(
  handle.clone(),
@@ -55,3 +99,13 @@ pub fn start(
 
  running
 }
+
+#[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))
+ }
+}

tests/servers/health_check_api/environment.rs

@@ -51,21 +51,21 @@ impl Environment<Stopped> {
 
  let register = self.registar.entries();
 
- debug!(target: "Health Check API", "Spawning task to launch the service ...");
+ debug!(target: "HEALTH CHECK API", "Spawning task to launch the service ...");
 
  let server = tokio::spawn(async move {
- debug!(target: "Health Check API", "Starting the server in a spawned task ...");
+ debug!(target: "HEALTH CHECK API", "Starting the server in a spawned task ...");
 
  server::start(self.state.bind_to, tx_start, rx_halt, register)
  .await
  .expect("it should start the health check service");
 
- debug!(target: "Health Check API", "Server started. Sending the binding {} ...", self.state.bind_to);
+ debug!(target: "HEALTH CHECK API", "Server started. Sending the binding {} ...", self.state.bind_to);
 
  self.state.bind_to
  });
 
- debug!(target: "Health Check API", "Waiting for spawning task to send the binding ...");
+ debug!(target: "HEALTH CHECK API", "Waiting for spawning task to send the binding ...");
 
  let binding = rx_start.await.expect("it should send service binding").address;