Merge #1161: Log assertions: add assertions for API log errors

5d49d48 test: [#1152] write assertions when API writes errors into logs (Jose Celano)
cc2840f feat: add an option to pass the request id in the API client (Jose Celano)
88d3d49 feat: add server socket address to logs in API (Jose Celano)

Pull request description:

  It adds test assertions for log errors in the context of the tracker API.

  Sample `ERROR` log:

  ```console
  cargo test -- --nocapture servers::api::v1::contract::authentication::should_not_authenticate_requests_when_the_token_is_empty
  ```

  ```output
  2024-12-26T11:13:00.203024Z ERROR API: response latency_ms=0 status_code=500 Internal Server Error server_socket_addr=127.0.0.1:35409 request_id=922cffeb-ed64-4d56-bbd0-400d6ea6f8d2
  ```

  We are using the `request_id` to find the log line because the tracing setup is global (shared by all tests). When the tracker API request is sent, the `request_id` is injected as an HTTP header.

Top commit has no ACKs.

Tree-SHA512: 0430296e2a9ca39b29fbd2cf34e73086c1084a80d58a8ac3994ee834713fe48c710b168d47929ef18240ef37e3fc98480b6ca15ba7313161981c2f0f5118dbbd

Author: josecelano

src/servers/apis/routes.rs

@@ -5,6 +5,7 @@
 //!
 //! All the API routes have the `/api` prefix and the version number as the
 //! first path segment. For example: `/api/v1/torrents`.
+use std::net::SocketAddr;
 use std::sync::Arc;
 use std::time::Duration;
 
@@ -35,7 +36,7 @@ use crate::servers::logging::Latency;
 /// Add all API routes to the router.
 #[allow(clippy::needless_pass_by_value)]
 #[instrument(skip(tracker, access_tokens))]
-pub fn router(tracker: Arc<Tracker>, access_tokens: Arc<AccessTokens>) -> Router {
+pub fn router(tracker: Arc<Tracker>, access_tokens: Arc<AccessTokens>, server_socket_addr: SocketAddr) -> Router {
     let router = Router::new();
 
     let api_url_prefix = "/api";
@@ -68,7 +69,7 @@ pub fn router(tracker: Arc<Tracker>, access_tokens: Arc<AccessTokens>) -> Router
                         target: API_LOG_TARGET,
                         tracing::Level::INFO, %method, %uri, %request_id, "request");
                 })
-                .on_response(|response: &Response, latency: Duration, span: &Span| {
+                .on_response(move |response: &Response, latency: Duration, span: &Span| {
                     let latency_ms = latency.as_millis();
                     let status_code = response.status();
                     let request_id = response
@@ -82,20 +83,20 @@ pub fn router(tracker: Arc<Tracker>, access_tokens: Arc<AccessTokens>) -> Router
                     if status_code.is_server_error() {
                         tracing::event!(
                             target: API_LOG_TARGET,
-                            tracing::Level::ERROR, %latency_ms, %status_code, %request_id, "response");
+                            tracing::Level::ERROR, %latency_ms, %status_code, %server_socket_addr, %request_id, "response");
                     } else {
                         tracing::event!(
                             target: API_LOG_TARGET,
-                            tracing::Level::INFO, %latency_ms, %status_code, %request_id, "response");
+                            tracing::Level::INFO, %latency_ms, %status_code, %server_socket_addr, %request_id, "response");
                     }
                 })
                 .on_failure(
-                    |failure_classification: ServerErrorsFailureClass, latency: Duration, _span: &Span| {
+                    move |failure_classification: ServerErrorsFailureClass, latency: Duration, _span: &Span| {
                         let latency = Latency::new(LatencyUnit::Millis, latency);
 
                         tracing::event!(
                             target: API_LOG_TARGET,
-                            tracing::Level::ERROR, %failure_classification, %latency, "response failed");
+                            tracing::Level::ERROR, %failure_classification, %latency, %server_socket_addr, "response failed");
                     },
                 ),
         )

src/servers/apis/server.rs

@@ -243,10 +243,11 @@ impl Launcher {
         tx_start: Sender<Started>,
         rx_halt: Receiver<Halted>,
     ) -> BoxFuture<'static, ()> {
-        let router = router(tracker, access_tokens);
         let socket = std::net::TcpListener::bind(self.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 router = router(tracker, access_tokens, address);
+
         let handle = Handle::new();
 
         tokio::task::spawn(graceful_shutdown(

tests/servers/api/v1/client.rs

@@ -1,5 +1,7 @@
+use hyper::HeaderMap;
 use reqwest::Response;
 use serde::Serialize;
+use uuid::Uuid;
 
 use crate::common::http::{Query, QueryParam, ReqwestQuery};
 use crate::servers::api::connection_info::ConnectionInfo;
@@ -18,90 +20,102 @@ impl Client {
         }
     }
 
-    pub async fn generate_auth_key(&self, seconds_valid: i32) -> Response {
-        self.post_empty(&format!("key/{}", &seconds_valid)).await
+    pub async fn generate_auth_key(&self, seconds_valid: i32, headers: Option<HeaderMap>) -> Response {
+        self.post_empty(&format!("key/{}", &seconds_valid), headers).await
     }
 
-    pub async fn add_auth_key(&self, add_key_form: AddKeyForm) -> Response {
-        self.post_form("keys", &add_key_form).await
+    pub async fn add_auth_key(&self, add_key_form: AddKeyForm, headers: Option<HeaderMap>) -> Response {
+        self.post_form("keys", &add_key_form, headers).await
     }
 
-    pub async fn delete_auth_key(&self, key: &str) -> Response {
-        self.delete(&format!("key/{}", &key)).await
+    pub async fn delete_auth_key(&self, key: &str, headers: Option<HeaderMap>) -> Response {
+        self.delete(&format!("key/{}", &key), headers).await
     }
 
-    pub async fn reload_keys(&self) -> Response {
-        self.get("keys/reload", Query::default()).await
+    pub async fn reload_keys(&self, headers: Option<HeaderMap>) -> Response {
+        self.get("keys/reload", Query::default(), headers).await
     }
 
-    pub async fn whitelist_a_torrent(&self, info_hash: &str) -> Response {
-        self.post_empty(&format!("whitelist/{}", &info_hash)).await
+    pub async fn whitelist_a_torrent(&self, info_hash: &str, headers: Option<HeaderMap>) -> Response {
+        self.post_empty(&format!("whitelist/{}", &info_hash), headers).await
     }
 
-    pub async fn remove_torrent_from_whitelist(&self, info_hash: &str) -> Response {
-        self.delete(&format!("whitelist/{}", &info_hash)).await
+    pub async fn remove_torrent_from_whitelist(&self, info_hash: &str, headers: Option<HeaderMap>) -> Response {
+        self.delete(&format!("whitelist/{}", &info_hash), headers).await
     }
 
-    pub async fn reload_whitelist(&self) -> Response {
-        self.get("whitelist/reload", Query::default()).await
+    pub async fn reload_whitelist(&self, headers: Option<HeaderMap>) -> Response {
+        self.get("whitelist/reload", Query::default(), headers).await
     }
 
-    pub async fn get_torrent(&self, info_hash: &str) -> Response {
-        self.get(&format!("torrent/{}", &info_hash), Query::default()).await
+    pub async fn get_torrent(&self, info_hash: &str, headers: Option<HeaderMap>) -> Response {
+        self.get(&format!("torrent/{}", &info_hash), Query::default(), headers).await
     }
 
-    pub async fn get_torrents(&self, params: Query) -> Response {
-        self.get("torrents", params).await
+    pub async fn get_torrents(&self, params: Query, headers: Option<HeaderMap>) -> Response {
+        self.get("torrents", params, headers).await
     }
 
-    pub async fn get_tracker_statistics(&self) -> Response {
-        self.get("stats", Query::default()).await
+    pub async fn get_tracker_statistics(&self, headers: Option<HeaderMap>) -> Response {
+        self.get("stats", Query::default(), headers).await
     }
 
-    pub async fn get(&self, path: &str, params: Query) -> Response {
+    pub async fn get(&self, path: &str, params: Query, headers: Option<HeaderMap>) -> Response {
         let mut query: Query = params;
 
         if let Some(token) = &self.connection_info.api_token {
             query.add_param(QueryParam::new("token", token));
         };
 
-        self.get_request_with_query(path, query).await
+        self.get_request_with_query(path, query, headers).await
     }
 
-    pub async fn post_empty(&self, path: &str) -> Response {
-        reqwest::Client::new()
+    pub async fn post_empty(&self, path: &str, headers: Option<HeaderMap>) -> Response {
+        let builder = reqwest::Client::new()
             .post(self.base_url(path).clone())
-            .query(&ReqwestQuery::from(self.query_with_token()))
-            .send()
-            .await
-            .unwrap()
+            .query(&ReqwestQuery::from(self.query_with_token()));
+
+        let builder = match headers {
+            Some(headers) => builder.headers(headers),
+            None => builder,
+        };
+
+        builder.send().await.unwrap()
     }
 
-    pub async fn post_form<T: Serialize + ?Sized>(&self, path: &str, form: &T) -> Response {
-        reqwest::Client::new()
+    pub async fn post_form<T: Serialize + ?Sized>(&self, path: &str, form: &T, headers: Option<HeaderMap>) -> Response {
+        let builder = reqwest::Client::new()
             .post(self.base_url(path).clone())
             .query(&ReqwestQuery::from(self.query_with_token()))
-            .json(&form)
-            .send()
-            .await
-            .unwrap()
+            .json(&form);
+
+        let builder = match headers {
+            Some(headers) => builder.headers(headers),
+            None => builder,
+        };
+
+        builder.send().await.unwrap()
     }
 
-    async fn delete(&self, path: &str) -> Response {
-        reqwest::Client::new()
+    async fn delete(&self, path: &str, headers: Option<HeaderMap>) -> Response {
+        let builder = reqwest::Client::new()
             .delete(self.base_url(path).clone())
-            .query(&ReqwestQuery::from(self.query_with_token()))
-            .send()
-            .await
-            .unwrap()
+            .query(&ReqwestQuery::from(self.query_with_token()));
+
+        let builder = match headers {
+            Some(headers) => builder.headers(headers),
+            None => builder,
+        };
+
+        builder.send().await.unwrap()
     }
 
-    pub async fn get_request_with_query(&self, path: &str, params: Query) -> Response {
-        get(&self.base_url(path), Some(params)).await
+    pub async fn get_request_with_query(&self, path: &str, params: Query, headers: Option<HeaderMap>) -> Response {
+        get(&self.base_url(path), Some(params), headers).await
     }
 
     pub async fn get_request(&self, path: &str) -> Response {
-        get(&self.base_url(path), None).await
+        get(&self.base_url(path), None, None).await
     }
 
     fn query_with_token(&self) -> Query {
@@ -116,18 +130,27 @@ impl Client {
     }
 }
 
-pub async fn get(path: &str, query: Option<Query>) -> Response {
-    match query {
-        Some(params) => reqwest::Client::builder()
-            .build()
-            .unwrap()
-            .get(path)
-            .query(&ReqwestQuery::from(params))
-            .send()
-            .await
-            .unwrap(),
-        None => reqwest::Client::builder().build().unwrap().get(path).send().await.unwrap(),
-    }
+pub async fn get(path: &str, query: Option<Query>, headers: Option<HeaderMap>) -> Response {
+    let builder = reqwest::Client::builder().build().unwrap();
+
+    let builder = match query {
+        Some(params) => builder.get(path).query(&ReqwestQuery::from(params)),
+        None => builder.get(path),
+    };
+
+    let builder = match headers {
+        Some(headers) => builder.headers(headers),
+        None => builder,
+    };
+
+    builder.send().await.unwrap()
+}
+
+/// Returns a `HeaderMap` with a request id header
+pub fn headers_with_request_id(request_id: Uuid) -> HeaderMap {
+    let mut headers = HeaderMap::new();
+    headers.insert("x-request-id", request_id.to_string().parse().unwrap());
+    headers
 }
 
 #[derive(Serialize, Debug)]

tests/servers/api/v1/contract/authentication.rs

@@ -1,9 +1,10 @@
 use torrust_tracker_test_helpers::configuration;
+use uuid::Uuid;
 
 use crate::common::http::{Query, QueryParam};
-use crate::common::logging::{self};
+use crate::common::logging::{self, logs_contains_a_line_with};
 use crate::servers::api::v1::asserts::{assert_token_not_valid, assert_unauthorized};
-use crate::servers::api::v1::client::Client;
+use crate::servers::api::v1::client::{headers_with_request_id, Client};
 use crate::servers::api::Started;
 
 #[tokio::test]
@@ -15,7 +16,7 @@ async fn should_authenticate_requests_by_using_a_token_query_param() {
     let token = env.get_connection_info().api_token.unwrap();
 
     let response = Client::new(env.get_connection_info())
-        .get_request_with_query("stats", Query::params([QueryParam::new("token", &token)].to_vec()))
+        .get_request_with_query("stats", Query::params([QueryParam::new("token", &token)].to_vec()), None)
         .await;
 
     assert_eq!(response.status(), 200);
@@ -29,12 +30,19 @@ async fn should_not_authenticate_requests_when_the_token_is_missing() {
 
     let env = Started::new(&configuration::ephemeral().into()).await;
 
+    let request_id = Uuid::new_v4();
+
     let response = Client::new(env.get_connection_info())
-        .get_request_with_query("stats", Query::default())
+        .get_request_with_query("stats", Query::default(), Some(headers_with_request_id(request_id)))
         .await;
 
     assert_unauthorized(response).await;
 
+    assert!(
+        logs_contains_a_line_with(&["ERROR", "API", &format!("{request_id}")]),
+        "Expected logs to contain: ERROR ... API ... request_id={request_id}"
+    );
+
     env.stop().await;
 }
 
@@ -44,12 +52,23 @@ async fn should_not_authenticate_requests_when_the_token_is_empty() {
 
     let env = Started::new(&configuration::ephemeral().into()).await;
 
+    let request_id = Uuid::new_v4();
+
     let response = Client::new(env.get_connection_info())
-        .get_request_with_query("stats", Query::params([QueryParam::new("token", "")].to_vec()))
+        .get_request_with_query(
+            "stats",
+            Query::params([QueryParam::new("token", "")].to_vec()),
+            Some(headers_with_request_id(request_id)),
+        )
         .await;
 
     assert_token_not_valid(response).await;
 
+    assert!(
+        logs_contains_a_line_with(&["ERROR", "API", &format!("{request_id}")]),
+        "Expected logs to contain: ERROR ... API ... request_id={request_id}"
+    );
+
     env.stop().await;
 }
 
@@ -59,12 +78,23 @@ async fn should_not_authenticate_requests_when_the_token_is_invalid() {
 
     let env = Started::new(&configuration::ephemeral().into()).await;
 
+    let request_id = Uuid::new_v4();
+
     let response = Client::new(env.get_connection_info())
-        .get_request_with_query("stats", Query::params([QueryParam::new("token", "INVALID TOKEN")].to_vec()))
+        .get_request_with_query(
+            "stats",
+            Query::params([QueryParam::new("token", "INVALID TOKEN")].to_vec()),
+            Some(headers_with_request_id(request_id)),
+        )
         .await;
 
     assert_token_not_valid(response).await;
 
+    assert!(
+        logs_contains_a_line_with(&["ERROR", "API", &format!("{request_id}")]),
+        "Expected logs to contain: ERROR ... API ... request_id={request_id}"
+    );
+
     env.stop().await;
 }