Merge #1022: Improve Tracing Part One

14e672e tracing: add spans to many functions (Cameron Garnham)
3dc75d5 tracing: init tracing-subscriber in intragration tests (Cameron Garnham)
e4aa1db tracing: qualify use of tracing macros (Cameron Garnham)

Pull request description:

  make better use of the modern features in the `tracing` library, first part.

ACKs for top commit:
  da2ce7:
    ACK 14e672e

Tree-SHA512: 3c913a1e7ea6ad5d088bdb08bd17bb30ff93e56fd37744e66fb869bca9870a0a019a2b1a29f56839cb6fe37f14afec27adce7ef5a81d3a58dd1eac13c563fe2b

packages/located-error/src/lib.rs

@@ -33,8 +33,6 @@ use std::error::Error;
 use std::panic::Location;
 use std::sync::Arc;
 
-use tracing::debug;
-
 pub type DynError = Arc<dyn std::error::Error + Send + Sync>;
 
 /// A generic wrapper around an error.
@@ -94,7 +92,7 @@ where
             source: Arc::new(self.0),
             location: Box::new(*std::panic::Location::caller()),
         };
-        debug!("{e}");
+        tracing::debug!("{e}");
         e
     }
 }

packages/test-helpers/src/configuration.rs

@@ -28,7 +28,7 @@ pub fn ephemeral() -> Configuration {
 
     let mut config = Configuration::default();
 
-    config.logging.threshold = Threshold::Off; // Change to `debug` for tests debugging
+    config.logging.threshold = Threshold::Off; // It should always be off here, the tests manage their own logging.
 
     // Ephemeral socket address for API
     let api_port = 0u16;

src/app.rs

@@ -25,7 +25,7 @@ use std::sync::Arc;
 
 use tokio::task::JoinHandle;
 use torrust_tracker_configuration::Configuration;
-use tracing::{info, warn};
+use tracing::instrument;
 
 use crate::bootstrap::jobs::{health_check_api, http_tracker, torrent_cleanup, tracker_apis, udp_tracker};
 use crate::servers::registar::Registar;
@@ -37,12 +37,13 @@ use crate::{core, servers};
 ///
 /// - Can't retrieve tracker keys from database.
 /// - Can't load whitelist from database.
+#[instrument(skip(config, tracker))]
 pub async fn start(config: &Configuration, tracker: Arc<core::Tracker>) -> Vec<JoinHandle<()>> {
     if config.http_api.is_none()
         && (config.udp_trackers.is_none() || config.udp_trackers.as_ref().map_or(true, std::vec::Vec::is_empty))
         && (config.http_trackers.is_none() || config.http_trackers.as_ref().map_or(true, std::vec::Vec::is_empty))
     {
-        warn!("No services enabled in configuration");
+        tracing::warn!("No services enabled in configuration");
     }
 
     let mut jobs: Vec<JoinHandle<()>> = Vec::new();
@@ -69,7 +70,7 @@ pub async fn start(config: &Configuration, tracker: Arc<core::Tracker>) -> Vec<J
     if let Some(udp_trackers) = &config.udp_trackers {
         for udp_tracker_config in udp_trackers {
             if tracker.is_private() {
-                warn!(
+                tracing::warn!(
                     "Could not start UDP tracker on: {} while in private mode. UDP is not safe for private trackers!",
                     udp_tracker_config.bind_address
                 );
@@ -78,7 +79,7 @@ pub async fn start(config: &Configuration, tracker: Arc<core::Tracker>) -> Vec<J
             }
         }
     } else {
-        info!("No UDP blocks in configuration");
+        tracing::info!("No UDP blocks in configuration");
     }
 
     // Start the HTTP blocks
@@ -96,7 +97,7 @@ pub async fn start(config: &Configuration, tracker: Arc<core::Tracker>) -> Vec<J
             };
         }
     } else {
-        info!("No HTTP blocks in configuration");
+        tracing::info!("No HTTP blocks in configuration");
     }
 
     // Start HTTP API
@@ -112,7 +113,7 @@ pub async fn start(config: &Configuration, tracker: Arc<core::Tracker>) -> Vec<J
             jobs.push(job);
         };
     } else {
-        info!("No API block in configuration");
+        tracing::info!("No API block in configuration");
     }
 
     // Start runners to remove torrents without peers, every interval

src/bootstrap/app.rs

@@ -16,7 +16,7 @@ use std::sync::Arc;
 use torrust_tracker_clock::static_time;
 use torrust_tracker_configuration::validator::Validator;
 use torrust_tracker_configuration::Configuration;
-use tracing::info;
+use tracing::instrument;
 
 use super::config::initialize_configuration;
 use crate::bootstrap;
@@ -30,6 +30,7 @@ use crate::shared::crypto::ephemeral_instance_keys;
 ///
 /// Setup can file if the configuration is invalid.
 #[must_use]
+#[instrument(skip())]
 pub fn setup() -> (Configuration, Arc<Tracker>) {
     let configuration = initialize_configuration();
 
@@ -39,7 +40,7 @@ pub fn setup() -> (Configuration, Arc<Tracker>) {
 
     let tracker = initialize_with_configuration(&configuration);
 
-    info!("Configuration:\n{}", configuration.clone().mask_secrets().to_json());
+    tracing::info!("Configuration:\n{}", configuration.clone().mask_secrets().to_json());
 
     (configuration, tracker)
 }
@@ -48,6 +49,7 @@ pub fn setup() -> (Configuration, Arc<Tracker>) {
 ///
 /// The configuration may be obtained from the environment (via config file or env vars).
 #[must_use]
+#[instrument(skip())]
 pub fn initialize_with_configuration(configuration: &Configuration) -> Arc<Tracker> {
     initialize_static();
     initialize_logging(configuration);
@@ -60,6 +62,7 @@ pub fn initialize_with_configuration(configuration: &Configuration) -> Arc<Track
 ///
 /// - The time when the application started.
 /// - An ephemeral instance random seed. This seed is used for encryption and it's changed when the main application process is restarted.
+#[instrument(skip())]
 pub fn initialize_static() {
     // Set the time of Torrust app starting
     lazy_static::initialize(&static_time::TIME_AT_APP_START);
@@ -73,13 +76,15 @@ pub fn initialize_static() {
 /// The tracker is the domain layer service. It's the entrypoint to make requests to the domain layer.
 /// It's used by other higher-level components like the UDP and HTTP trackers or the tracker API.
 #[must_use]
+#[instrument(skip(config))]
 pub fn initialize_tracker(config: &Configuration) -> Tracker {
     tracker_factory(config)
 }
 
 /// It initializes the log threshold, format and channel.
 ///
 /// See [the logging setup](crate::bootstrap::logging::setup) for more info about logging.
+#[instrument(skip(config))]
 pub fn initialize_logging(config: &Configuration) {
     bootstrap::logging::setup(config);
 }

src/bootstrap/jobs/health_check_api.rs

@@ -17,7 +17,7 @@
 use tokio::sync::oneshot;
 use tokio::task::JoinHandle;
 use torrust_tracker_configuration::HealthCheckApi;
-use tracing::info;
+use tracing::instrument;
 
 use super::Started;
 use crate::servers::health_check_api::{server, HEALTH_CHECK_API_LOG_TARGET};
@@ -35,6 +35,8 @@ use crate::servers::signals::Halted;
 /// # Panics
 ///
 /// It would panic if unable to send the  `ApiServerJobStarted` notice.
+#[allow(clippy::async_yields_async)]
+#[instrument(skip(config, register))]
 pub async fn start_job(config: &HealthCheckApi, register: ServiceRegistry) -> JoinHandle<()> {
     let bind_addr = config.bind_address;
 
@@ -45,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_LOG_TARGET, "Starting on: {protocol}://{}", bind_addr);
+        tracing::info!(target: HEALTH_CHECK_API_LOG_TARGET, "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_LOG_TARGET, "Stopped server running on: {protocol}://{}", bind_addr);
+            tracing::info!(target: HEALTH_CHECK_API_LOG_TARGET, "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_LOG_TARGET, "{STARTED_ON}: {protocol}://{}", msg.address),
+        Ok(msg) => tracing::info!(target: HEALTH_CHECK_API_LOG_TARGET, "{STARTED_ON}: {protocol}://{}", msg.address),
         Err(e) => panic!("the Health Check API server was dropped: {e}"),
     }
 

src/bootstrap/jobs/http_tracker.rs

@@ -16,6 +16,7 @@ use std::sync::Arc;
 use axum_server::tls_rustls::RustlsConfig;
 use tokio::task::JoinHandle;
 use torrust_tracker_configuration::HttpTracker;
+use tracing::instrument;
 
 use super::make_rust_tls;
 use crate::core;
@@ -32,6 +33,7 @@ use crate::servers::registar::ServiceRegistrationForm;
 ///
 /// It would panic if the `config::HttpTracker` struct would contain inappropriate values.
 ///
+#[instrument(skip(config, tracker, form))]
 pub async fn start_job(
     config: &HttpTracker,
     tracker: Arc<core::Tracker>,
@@ -49,6 +51,8 @@ pub async fn start_job(
     }
 }
 
+#[allow(clippy::async_yields_async)]
+#[instrument(skip(socket, tls, tracker, form))]
 async fn start_v1(
     socket: SocketAddr,
     tls: Option<RustlsConfig>,

src/bootstrap/jobs/mod.rs

@@ -20,6 +20,7 @@ pub struct Started {
     pub address: std::net::SocketAddr,
 }
 
+#[instrument(skip(opt_tsl_config))]
 pub async fn make_rust_tls(opt_tsl_config: &Option<TslConfig>) -> Option<Result<RustlsConfig, Error>> {
     match opt_tsl_config {
         Some(tsl_config) => {
@@ -32,8 +33,8 @@ pub async fn make_rust_tls(opt_tsl_config: &Option<TslConfig>) -> Option<Result<
                 }));
             }
 
-            info!("Using https: cert path: {cert}.");
-            info!("Using https: key path: {key}.");
+            tracing::info!("Using https: cert path: {cert}.");
+            tracing::info!("Using https: key path: {key}.");
 
             Some(
                 RustlsConfig::from_pem_file(cert, key)
@@ -89,7 +90,7 @@ use axum_server::tls_rustls::RustlsConfig;
 use thiserror::Error;
 use torrust_tracker_configuration::TslConfig;
 use torrust_tracker_located_error::{DynError, LocatedError};
-use tracing::info;
+use tracing::instrument;
 
 /// Error returned by the Bootstrap Process.
 #[derive(Error, Debug)]

src/bootstrap/jobs/torrent_cleanup.rs

@@ -15,7 +15,7 @@ use std::sync::Arc;
 use chrono::Utc;
 use tokio::task::JoinHandle;
 use torrust_tracker_configuration::Core;
-use tracing::info;
+use tracing::instrument;
 
 use crate::core;
 
@@ -25,6 +25,7 @@ use crate::core;
 ///
 /// Refer to [`torrust-tracker-configuration documentation`](https://docs.rs/torrust-tracker-configuration) for more info about that option.
 #[must_use]
+#[instrument(skip(config, tracker))]
 pub fn start_job(config: &Core, tracker: &Arc<core::Tracker>) -> JoinHandle<()> {
     let weak_tracker = std::sync::Arc::downgrade(tracker);
     let interval = config.inactive_peer_cleanup_interval;
@@ -37,15 +38,15 @@ pub fn start_job(config: &Core, tracker: &Arc<core::Tracker>) -> JoinHandle<()>
         loop {
             tokio::select! {
                 _ = tokio::signal::ctrl_c() => {
-                    info!("Stopping torrent cleanup job..");
+                    tracing::info!("Stopping torrent cleanup job..");
                     break;
                 }
                 _ = interval.tick() => {
                     if let Some(tracker) = weak_tracker.upgrade() {
                         let start_time = Utc::now().time();
-                        info!("Cleaning up torrents..");
+                        tracing::info!("Cleaning up torrents..");
                         tracker.cleanup_torrents();
-                        info!("Cleaned up torrents in: {}ms", (Utc::now().time() - start_time).num_milliseconds());
+                        tracing::info!("Cleaned up torrents in: {}ms", (Utc::now().time() - start_time).num_milliseconds());
                     } else {
                         break;
                     }

src/bootstrap/jobs/tracker_apis.rs

@@ -26,6 +26,7 @@ use std::sync::Arc;
 use axum_server::tls_rustls::RustlsConfig;
 use tokio::task::JoinHandle;
 use torrust_tracker_configuration::{AccessTokens, HttpApi};
+use tracing::instrument;
 
 use super::make_rust_tls;
 use crate::core;
@@ -53,6 +54,7 @@ pub struct ApiServerJobStarted();
 /// It would panic if unable to send the  `ApiServerJobStarted` notice.
 ///
 ///
+#[instrument(skip(config, tracker, form))]
 pub async fn start_job(
     config: &HttpApi,
     tracker: Arc<core::Tracker>,
@@ -72,6 +74,8 @@ pub async fn start_job(
     }
 }
 
+#[allow(clippy::async_yields_async)]
+#[instrument(skip(socket, tls, tracker, form, access_tokens))]
 async fn start_v1(
     socket: SocketAddr,
     tls: Option<RustlsConfig>,

src/bootstrap/jobs/udp_tracker.rs

@@ -10,7 +10,7 @@ use std::sync::Arc;
 
 use tokio::task::JoinHandle;
 use torrust_tracker_configuration::UdpTracker;
-use tracing::debug;
+use tracing::instrument;
 
 use crate::core;
 use crate::servers::registar::ServiceRegistrationForm;
@@ -28,6 +28,8 @@ use crate::servers::udp::UDP_TRACKER_LOG_TARGET;
 /// It will panic if it is unable to start the UDP service.
 /// It will panic if the task did not finish successfully.
 #[must_use]
+#[allow(clippy::async_yields_async)]
+#[instrument(skip(config, tracker, form))]
 pub async fn start_job(config: &UdpTracker, tracker: Arc<core::Tracker>, form: ServiceRegistrationForm) -> JoinHandle<()> {
     let bind_to = config.bind_address;
 
@@ -37,8 +39,8 @@ pub async fn start_job(config: &UdpTracker, tracker: Arc<core::Tracker>, form: S
         .expect("it should be able to start the udp tracker");
 
     tokio::spawn(async move {
-        debug!(target: UDP_TRACKER_LOG_TARGET, "Wait for launcher (UDP service) to finish ...");
-        debug!(target: UDP_TRACKER_LOG_TARGET, "Is halt channel closed before waiting?: {}", server.state.halt_task.is_closed());
+        tracing::debug!(target: UDP_TRACKER_LOG_TARGET, "Wait for launcher (UDP service) to finish ...");
+        tracing::debug!(target: UDP_TRACKER_LOG_TARGET, "Is halt channel closed before waiting?: {}", server.state.halt_task.is_closed());
 
         assert!(
             !server.state.halt_task.is_closed(),
@@ -51,6 +53,6 @@ pub async fn start_job(config: &UdpTracker, tracker: Arc<core::Tracker>, form: S
             .await
             .expect("it should be able to join to the udp tracker task");
 
-        debug!(target: UDP_TRACKER_LOG_TARGET, "Is halt channel closed after finishing the server?: {}", server.state.halt_task.is_closed());
+        tracing::debug!(target: UDP_TRACKER_LOG_TARGET, "Is halt channel closed after finishing the server?: {}", server.state.halt_task.is_closed());
     })
 }

src/bootstrap/logging.rs

@@ -14,7 +14,6 @@
 use std::sync::Once;
 
 use torrust_tracker_configuration::{Configuration, Threshold};
-use tracing::info;
 use tracing::level_filters::LevelFilter;
 
 static INIT: Once = Once::new();
@@ -54,7 +53,7 @@ fn tracing_stdout_init(filter: LevelFilter, style: &TraceStyle) {
         TraceStyle::Json => builder.json().init(),
     };
 
-    info!("Logging initialized");
+    tracing::info!("Logging initialized");
 }
 
 #[derive(Debug)]

src/console/ci/e2e/docker.rs

@@ -4,8 +4,6 @@ use std::process::{Command, Output};
 use std::thread::sleep;
 use std::time::{Duration, Instant};
 
-use tracing::{debug, info};
-
 /// Docker command wrapper.
 pub struct Docker {}
 
@@ -20,7 +18,7 @@ impl Drop for RunningContainer {
     /// Ensures that the temporary container is stopped when the struct goes out
     /// of scope.
     fn drop(&mut self) {
-        info!("Dropping running container: {}", self.name);
+        tracing::info!("Dropping running container: {}", self.name);
         if Docker::is_container_running(&self.name) {
             let _unused = Docker::stop(self);
         }
@@ -89,7 +87,7 @@ impl Docker {
 
         let args = [initial_args, env_var_args, port_args, [image.to_string()].to_vec()].concat();
 
-        debug!("Docker run args: {:?}", args);
+        tracing::debug!("Docker run args: {:?}", args);
 
         let output = Command::new("docker").args(args).output()?;
 
@@ -176,7 +174,7 @@ impl Docker {
 
             let output_str = String::from_utf8_lossy(&output.stdout);
 
-            info!("Waiting until container is healthy: {:?}", output_str);
+            tracing::info!("Waiting until container is healthy: {:?}", output_str);
 
             if output_str.contains("(healthy)") {
                 return true;