refactor: [torrust#884] move from log to tracing crate

josecelano · josecelano · commit 69f100ab7d38 · 2024-06-10T17:01:40.000+01:00
diff --git a/packages/configuration/src/lib.rs b/packages/configuration/src/lib.rs
@@ -64,7 +64,7 @@ impl Info {
         let env_var_config_toml_path = ENV_VAR_CONFIG_TOML_PATH.to_string();
 
         let config_toml = if let Ok(config_toml) = env::var(env_var_config_toml) {
-            println!("Loading configuration from environment variable {config_toml} ...");
+            println!("Loading configuration from environment variable:\n {config_toml}");
             Some(config_toml)
         } else {
             None
diff --git a/share/default/config/tracker.e2e.container.sqlite3.toml b/share/default/config/tracker.e2e.container.sqlite3.toml
@@ -11,3 +11,7 @@ ssl_key_path = "/var/lib/torrust/tracker/tls/localhost.key"
 [http_api]
 ssl_cert_path = "/var/lib/torrust/tracker/tls/localhost.crt"
 ssl_key_path = "/var/lib/torrust/tracker/tls/localhost.key"
+
+[health_check_api]
+# Must be bound to wildcard IP to be accessible from outside the container
+bind_address = "0.0.0.0:1313"
diff --git a/src/bootstrap/logging.rs b/src/bootstrap/logging.rs
@@ -46,7 +46,7 @@ fn config_level_or_default(log_level: &Option<LogLevel>) -> LevelFilter {
 }
 
 fn tracing_stdout_init(filter: LevelFilter, style: &TraceStyle) {
-    let builder = tracing_subscriber::fmt().with_max_level(filter);
+    let builder = tracing_subscriber::fmt().with_max_level(filter).with_ansi(false);
 
     let () = match style {
         TraceStyle::Default => builder.init(),
diff --git a/src/console/ci/e2e/docker.rs b/src/console/ci/e2e/docker.rs
@@ -176,6 +176,8 @@ impl Docker {
 
             let output_str = String::from_utf8_lossy(&output.stdout);
 
+            info!("Waiting until container is healthy: {:?}", output_str);
+
             if output_str.contains("(healthy)") {
                 return true;
             }
diff --git a/src/console/ci/e2e/logs_parser.rs b/src/console/ci/e2e/logs_parser.rs
@@ -1,9 +1,9 @@
 //! Utilities to parse Torrust Tracker logs.
 use serde::{Deserialize, Serialize};
 
-const UDP_TRACKER_PATTERN: &str = "INFO UDP TRACKER: Starting on: udp://";
-const HTTP_TRACKER_PATTERN: &str = "INFO HTTP TRACKER: Starting on: ";
-const HEALTH_CHECK_PATTERN: &str = "INFO HEALTH CHECK API: Starting on: ";
+const UDP_TRACKER_PATTERN: &str = "UDP TRACKER: Started on: udp://";
+const HTTP_TRACKER_PATTERN: &str = "HTTP TRACKER: Started on: ";
+const HEALTH_CHECK_PATTERN: &str = "HEALTH CHECK API: Started on: ";
 
 #[derive(Serialize, Deserialize, Debug, Default)]
 pub struct RunningServices {
@@ -19,16 +19,17 @@ impl RunningServices {
     ///
     /// ```text
     /// Loading configuration from default configuration file: `./share/default/config/tracker.development.sqlite3.toml` ...
-    /// 2024-06-10T14:26:10.040894Z  INFO torrust_tracker::bootstrap::logging: logging initialized.
-    /// 2024-06-10T14:26:10.041363Z  INFO UDP TRACKER: Starting on: udp://0.0.0.0:6969
-    /// 2024-06-10T14:26:10.041386Z  INFO torrust_tracker::bootstrap::jobs: TLS not enabled
-    /// 2024-06-10T14:26:10.041420Z  INFO HTTP TRACKER: Starting on: http://0.0.0.0:7070
-    /// 2024-06-10T14:26:10.041516Z  INFO HTTP TRACKER: Started on: http://0.0.0.0:7070
-    /// 2024-06-10T14:26:10.041521Z  INFO torrust_tracker::bootstrap::jobs: TLS not enabled
-    /// 2024-06-10T14:26:10.041611Z  INFO API: Starting on http://127.0.0.1:1212
-    /// 2024-06-10T14:26:10.041614Z  INFO API: Started on http://127.0.0.1:1212
-    /// 2024-06-10T14:26:10.041623Z  INFO HEALTH CHECK API: Starting on: http://127.0.0.1:1313
-    /// 2024-06-10T14:26:10.041657Z  INFO HEALTH CHECK API: Started on: http://127.0.0.1:1313
+    /// 2024-06-10T14:59:57.973525Z  INFO torrust_tracker::bootstrap::logging: logging initialized.
+    /// 2024-06-10T14:59:57.974306Z  INFO UDP TRACKER: Starting on: udp://0.0.0.0:6969
+    /// 2024-06-10T14:59:57.974316Z  INFO UDP TRACKER: Started on: udp://0.0.0.0:6969
+    /// 2024-06-10T14:59:57.974332Z  INFO torrust_tracker::bootstrap::jobs: TLS not enabled
+    /// 2024-06-10T14:59:57.974366Z  INFO HTTP TRACKER: Starting on: http://0.0.0.0:7070
+    /// 2024-06-10T14:59:57.974513Z  INFO HTTP TRACKER: Started on: http://0.0.0.0:7070
+    /// 2024-06-10T14:59:57.974521Z  INFO torrust_tracker::bootstrap::jobs: TLS not enabled
+    /// 2024-06-10T14:59:57.974615Z  INFO API: Starting on http://127.0.0.1:1212
+    /// 2024-06-10T14:59:57.974618Z  INFO API: Started on http://127.0.0.1:1212
+    /// 2024-06-10T14:59:57.974643Z  INFO HEALTH CHECK API: Starting on: http://127.0.0.1:1313
+    /// 2024-06-10T14:59:57.974760Z  INFO HEALTH CHECK API: Started on: http://127.0.0.1:1313
     /// ```
     ///
     /// It would extract these services:
@@ -46,6 +47,9 @@ impl RunningServices {
     ///    ]
     /// }
     /// ```
+    ///
+    /// NOTICE: Using colors in the console output could affect this method 
+    /// due to the hidden control chars.
     #[must_use]
     pub fn parse_from_logs(logs: &str) -> Self {
         let mut udp_trackers: Vec<String> = Vec::new();
@@ -85,20 +89,45 @@ mod tests {
 
     #[test]
     fn it_should_parse_from_logs_with_valid_logs() {
-        let logs = "\
-            INFO UDP TRACKER: Starting on: udp://0.0.0.0:8080\n\
-            INFO HTTP TRACKER: Starting on: 0.0.0.0:9090\n\
-            INFO HEALTH CHECK API: Starting on: 0.0.0.0:10010";
-        let running_services = RunningServices::parse_from_logs(logs);
+        let log = r#"
+            Loading configuration from environment variable db_path = "/var/lib/torrust/tracker/database/sqlite3.db"
+
+            [[udp_trackers]]
+            enabled = true
+
+            [[http_trackers]]
+            enabled = true
+            ssl_cert_path = "/var/lib/torrust/tracker/tls/localhost.crt"
+            ssl_key_path = "/var/lib/torrust/tracker/tls/localhost.key"
+
+            [http_api]
+            ssl_cert_path = "/var/lib/torrust/tracker/tls/localhost.crt"
+            ssl_key_path = "/var/lib/torrust/tracker/tls/localhost.key"
+            ...
+            Loading configuration from file: `/etc/torrust/tracker/tracker.toml` ...
+            2024-06-10T15:09:54.411031Z  INFO torrust_tracker::bootstrap::logging: logging initialized.
+            2024-06-10T15:09:54.415084Z  INFO UDP TRACKER: Starting on: udp://0.0.0.0:6969
+            2024-06-10T15:09:54.415091Z  INFO UDP TRACKER: Started on: udp://0.0.0.0:6969
+            2024-06-10T15:09:54.415104Z  INFO torrust_tracker::bootstrap::jobs: TLS not enabled
+            2024-06-10T15:09:54.415130Z  INFO HTTP TRACKER: Starting on: http://0.0.0.0:7070
+            2024-06-10T15:09:54.415266Z  INFO HTTP TRACKER: Started on: http://0.0.0.0:7070
+            2024-06-10T15:09:54.415275Z  INFO torrust_tracker::bootstrap::jobs: TLS not enabled
+            2024-06-10T15:09:54.415403Z  INFO API: Starting on http://127.0.0.1:1212
+            2024-06-10T15:09:54.415411Z  INFO API: Started on http://127.0.0.1:1212
+            2024-06-10T15:09:54.415430Z  INFO HEALTH CHECK API: Starting on: http://127.0.0.1:1313
+            2024-06-10T15:09:54.415472Z  INFO HEALTH CHECK API: Started on: http://127.0.0.1:1313
+            "#;
+
+        let running_services = RunningServices::parse_from_logs(log);
 
-        assert_eq!(running_services.udp_trackers, vec!["127.0.0.1:8080"]);
-        assert_eq!(running_services.http_trackers, vec!["127.0.0.1:9090"]);
-        assert_eq!(running_services.health_checks, vec!["127.0.0.1:10010/health_check"]);
+        assert_eq!(running_services.udp_trackers, vec!["127.0.0.1:6969"]);
+        assert_eq!(running_services.http_trackers, vec!["http://127.0.0.1:7070"]);
+        assert_eq!(running_services.health_checks, vec!["http://127.0.0.1:1313/health_check"]);
     }
 
     #[test]
     fn it_should_ignore_logs_with_no_matching_lines() {
-        let logs = "[Other Service][INFO] Starting on: 0.0.0.0:7070";
+        let logs = "[Other Service][INFO] Started on: 0.0.0.0:7070";
         let running_services = RunningServices::parse_from_logs(logs);
 
         assert!(running_services.udp_trackers.is_empty());
diff --git a/src/console/ci/e2e/runner.rs b/src/console/ci/e2e/runner.rs
@@ -60,6 +60,11 @@ pub fn run() {
 
     let running_services = tracker_container.running_services();
 
+    info!(
+        "Running services:\n {}",
+        serde_json::to_string_pretty(&running_services).expect("running services to be serializable to JSON")
+    );
+
     assert_there_is_at_least_one_service_per_type(&running_services);
 
     let tracker_checker_config =
@@ -78,7 +83,7 @@ pub fn run() {
 }
 
 fn tracing_stdout_init(filter: LevelFilter) {
-    tracing_subscriber::fmt().with_max_level(filter).init();
+    tracing_subscriber::fmt().with_max_level(filter).with_ansi(false).init();
     info!("logging initialized.");
 }
 
diff --git a/src/console/ci/e2e/tracker_container.rs b/src/console/ci/e2e/tracker_container.rs
@@ -2,7 +2,7 @@ use std::time::Duration;
 
 use rand::distributions::Alphanumeric;
 use rand::Rng;
-use tracing::{debug, error, info};
+use tracing::{error, info};
 
 use super::docker::{RunOptions, RunningContainer};
 use super::logs_parser::RunningServices;
@@ -72,7 +72,7 @@ impl TrackerContainer {
     pub fn running_services(&self) -> RunningServices {
         let logs = Docker::logs(&self.name).expect("Logs should be captured from running container");
 
-        debug!("Parsing running services from logs. Logs :\n{logs}");
+        info!("Parsing running services from logs. Logs :\n{logs}");
 
         RunningServices::parse_from_logs(&logs)
     }
diff --git a/src/console/clients/checker/app.rs b/src/console/clients/checker/app.rs
@@ -58,7 +58,7 @@ pub async fn run() -> Result<Vec<CheckResult>> {
 }
 
 fn tracing_stdout_init(filter: LevelFilter) {
-    tracing_subscriber::fmt().with_max_level(filter).init();
+    tracing_subscriber::fmt().with_max_level(filter).with_ansi(false).init();
     info!("logging initialized.");
 }
 
diff --git a/src/console/clients/udp/app.rs b/src/console/clients/udp/app.rs
@@ -127,7 +127,7 @@ pub async fn run() -> anyhow::Result<()> {
 }
 
 fn tracing_stdout_init(filter: LevelFilter) {
-    tracing_subscriber::fmt().with_max_level(filter).init();
+    tracing_subscriber::fmt().with_max_level(filter).with_ansi(false).init();
     info!("logging initialized.");
 }
 
diff --git a/src/servers/udp/server.rs b/src/servers/udp/server.rs
@@ -273,7 +273,7 @@ impl Udp {
             .send(Started { address })
             .expect("the UDP Tracker service should not be dropped");
 
-        debug!(target: "UDP TRACKER", "Started on: udp://{}", address);
+        info!(target: "UDP TRACKER", "Started on: udp://{}", address);
 
         let stop = running.abort_handle();
 

Original file line number	Diff line number	Diff line change
`@@ -46,7 +46,7 @@ fn config_level_or_default(log_level: &Option<LogLevel>) -> LevelFilter {`
`46`	`46`	`}`
`47`	`47`
`48`	`48`	`fn tracing_stdout_init(filter: LevelFilter, style: &TraceStyle) {`
`49`		`- let builder = tracing_subscriber::fmt().with_max_level(filter);`
	`49`	`+ let builder = tracing_subscriber::fmt().with_max_level(filter).with_ansi(false);`
`50`	`50`
`51`	`51`	`let () = match style {`
`52`	`52`	`TraceStyle::Default => builder.init(),`
Original file line number	Diff line number	Diff line change
`@@ -176,6 +176,8 @@ impl Docker {`
`176`	`176`
`177`	`177`	`let output_str = String::from_utf8_lossy(&output.stdout);`
`178`	`178`
	`179`	`+ info!("Waiting until container is healthy: {:?}", output_str);`
	`180`	`+`
`179`	`181`	`if output_str.contains("(healthy)") {`
`180`	`182`	`return true;`
`181`	`183`	`}`
Original file line number	Diff line number	Diff line change
`@@ -58,7 +58,7 @@ pub async fn run() -> Result<Vec<CheckResult>> {`
`58`	`58`	`}`
`59`	`59`
`60`	`60`	`fn tracing_stdout_init(filter: LevelFilter) {`
`61`		`- tracing_subscriber::fmt().with_max_level(filter).init();`
	`61`	`+ tracing_subscriber::fmt().with_max_level(filter).with_ansi(false).init();`
`62`	`62`	`info!("logging initialized.");`
`63`	`63`	`}`
`64`	`64`
Original file line number	Diff line number	Diff line change
`@@ -127,7 +127,7 @@ pub async fn run() -> anyhow::Result<()> {`
`127`	`127`	`}`
`128`	`128`
`129`	`129`	`fn tracing_stdout_init(filter: LevelFilter) {`
`130`		`- tracing_subscriber::fmt().with_max_level(filter).init();`
	`130`	`+ tracing_subscriber::fmt().with_max_level(filter).with_ansi(false).init();`
`131`	`131`	`info!("logging initialized.");`
`132`	`132`	`}`
`133`	`133`