From 5a1d8757bbc0bde49f09a3528f7ffdf5e03624cd Mon Sep 17 00:00:00 2001 From: Cameron Garnham Date: Tue, 9 Apr 2024 03:53:44 +0800 Subject: [PATCH 1/2] other: add vscode workspace to ignorefile --- .gitignore | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/.gitignore b/.gitignore index c1abad7e..e2e39bee 100644 --- a/.gitignore +++ b/.gitignore @@ -12,4 +12,5 @@ /tracker.* /tracker.toml callgrind.out -perf.data* \ No newline at end of file +perf.data* +*.code-workspace From a086cff58fe30a62a2a598a968ca3b51218f41b3 Mon Sep 17 00:00:00 2001 From: Cameron Garnham Date: Tue, 9 Apr 2024 12:43:43 +0800 Subject: [PATCH 2/2] dev: move to tracing with subscriber Replaces log with fern. Better async support. --- Cargo.lock | 106 ++++++++++---- Cargo.toml | 10 +- docs/benchmarking.md | 6 +- packages/configuration/src/lib.rs | 97 +++++++++++-- packages/located-error/Cargo.toml | 2 +- packages/located-error/src/lib.rs | 2 +- packages/test-helpers/src/configuration.rs | 6 +- .../config/tracker.container.mysql.toml | 3 +- .../config/tracker.container.sqlite3.toml | 3 +- .../config/tracker.development.sqlite3.toml | 3 +- .../config/tracker.e2e.container.sqlite3.toml | 3 +- .../config/tracker.udp.benchmarking.toml | 2 +- src/app.rs | 2 +- src/bootstrap/app.rs | 12 +- src/bootstrap/jobs/health_check_api.rs | 2 +- src/bootstrap/jobs/http_tracker.rs | 2 +- src/bootstrap/jobs/mod.rs | 2 +- src/bootstrap/jobs/torrent_cleanup.rs | 2 +- src/bootstrap/jobs/tracker_apis.rs | 2 +- src/bootstrap/jobs/udp_tracker.rs | 2 +- src/bootstrap/logging.rs | 60 -------- src/bootstrap/mod.rs | 2 +- src/bootstrap/tracing.rs | 131 ++++++++++++++++++ src/console/ci/e2e/docker.rs | 10 +- src/console/ci/e2e/logs_parser.rs | 114 --------------- src/console/ci/e2e/mod.rs | 2 +- src/console/ci/e2e/runner.rs | 27 +--- src/console/ci/e2e/trace_parser.rs | 115 +++++++++++++++ src/console/ci/e2e/tracker_checker.rs | 2 +- src/console/ci/e2e/tracker_container.rs | 24 ++-- src/console/clients/checker/app.rs | 25 +--- src/console/clients/checker/checks/http.rs | 2 +- src/console/clients/checker/checks/udp.rs | 2 +- src/console/clients/checker/logger.rs | 20 +-- src/console/clients/udp/app.rs | 25 +--- src/console/clients/udp/checker.rs | 2 +- src/console/profiling.rs | 6 +- src/core/auth.rs | 2 +- src/core/databases/mysql.rs | 2 +- src/core/mod.rs | 4 +- src/core/statistics.rs | 2 +- src/lib.rs | 2 +- src/main.rs | 2 +- src/servers/apis/mod.rs | 2 +- src/servers/apis/server.rs | 2 +- .../apis/v1/context/torrent/handlers.rs | 2 +- src/servers/health_check_api/server.rs | 3 +- src/servers/http/server.rs | 2 +- src/servers/http/v1/handlers/announce.rs | 2 +- src/servers/http/v1/handlers/scrape.rs | 2 +- src/servers/registar.rs | 2 +- src/servers/signals.rs | 2 +- src/servers/udp/handlers.rs | 12 +- src/servers/udp/mod.rs | 2 +- src/servers/udp/server.rs | 4 +- src/servers/udp/{logging.rs => tracing.rs} | 10 +- src/shared/bit_torrent/tracker/udp/client.rs | 2 +- tests/servers/health_check_api/environment.rs | 2 +- 58 files changed, 534 insertions(+), 369 deletions(-) delete mode 100644 src/bootstrap/logging.rs create mode 100644 src/bootstrap/tracing.rs delete mode 100644 src/console/ci/e2e/logs_parser.rs create mode 100644 src/console/ci/e2e/trace_parser.rs rename src/servers/udp/{logging.rs => tracing.rs} (91%) diff --git a/Cargo.lock b/Cargo.lock index 6b9be523..cf25cb29 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1288,15 +1288,6 @@ version = "2.0.2" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "658bd65b1cf4c852a3cc96f18a8ce7b5640f6b703f905c7d74532294c2a63984" -[[package]] -name = "fern" -version = "0.6.2" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "d9f0c14694cbd524c8720dd69b0e3179344f04ebb5f90f2e4a440c6ea3b2f1ee" -dependencies = [ - "log", -] - [[package]] name = "flate2" version = "1.0.28" @@ -2359,6 +2350,16 @@ version = "0.7.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "e9e591e719385e6ebaeb5ce5d3887f7d5676fceca6411d1925ccc95745f3d6f7" +[[package]] +name = "nu-ansi-term" +version = "0.46.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "77a8165726e8236064dbb45459242600304b42a5ea24ee2948e18e023bf7ba84" +dependencies = [ + "overload", + "winapi", +] + [[package]] name = "num-bigint" version = "0.4.4" @@ -2479,6 +2480,12 @@ dependencies = [ "hashbrown 0.13.2", ] +[[package]] +name = "overload" +version = "0.1.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "b15813163c1d831bf4a13c3610c05c0d03b39feb07f7e09fa234dac9b15aaf39" + [[package]] name = "parking" version = "2.2.0" @@ -3496,6 +3503,15 @@ dependencies = [ "digest", ] +[[package]] +name = "sharded-slab" +version = "0.1.7" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f40ca3c46823713e0d4209592e8d6e826aa57e928f09752619fc696c499637f6" +dependencies = [ + "lazy_static", +] + [[package]] name = "shlex" version = "1.3.0" @@ -3729,6 +3745,16 @@ dependencies = [ "syn 2.0.58", ] +[[package]] +name = "thread_local" +version = "1.1.8" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "8b9ef9bad013ada3808854ceac7b46812a6465ba368859a37e2100283d2d719c" +dependencies = [ + "cfg-if", + "once_cell", +] + [[package]] name = "time" version = "0.3.34" @@ -3931,13 +3957,11 @@ dependencies = [ "crossbeam-skiplist", "dashmap", "derive_more", - "fern", "futures", "hex-literal", "hyper", "lazy_static", "local-ip-address", - "log", "mockall", "multimap", "percent-encoding", @@ -3962,8 +3986,8 @@ dependencies = [ "torrust-tracker-test-helpers", "torrust-tracker-torrent-repository", "tower-http", - "trace", "tracing", + "tracing-subscriber", "url", "uuid", ] @@ -4004,8 +4028,8 @@ dependencies = [ name = "torrust-tracker-located-error" version = "3.0.0-alpha.12-develop" dependencies = [ - "log", "thiserror", + "tracing", ] [[package]] @@ -4095,17 +4119,6 @@ version = "0.3.2" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "b6bc1c9ce2b5135ac7f93c72918fc37feb872bdc6a5533a8b85eb4b86bfdae52" -[[package]] -name = "trace" -version = "0.1.7" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "9ad0c048e114d19d1140662762bfdb10682f3bc806d8be18af846600214dd9af" -dependencies = [ - "proc-macro2", - "quote", - "syn 1.0.109", -] - [[package]] name = "tracing" version = "0.1.40" @@ -4136,6 +4149,45 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "c06d3da6113f116aaee68e4d601191614c9053067f9ab7f6edbcb161237daa54" dependencies = [ "once_cell", + "valuable", +] + +[[package]] +name = "tracing-log" +version = "0.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ee855f1f400bd0e5c02d150ae5de3840039a3f54b025156404e34c23c03f47c3" +dependencies = [ + "log", + "once_cell", + "tracing-core", +] + +[[package]] +name = "tracing-serde" +version = "0.1.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "bc6b213177105856957181934e4920de57730fc69bf42c37ee5bb664d406d9e1" +dependencies = [ + "serde", + "tracing-core", +] + +[[package]] +name = "tracing-subscriber" +version = "0.3.18" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ad0f048c97dbd9faa9b7df56362b8ebcaa52adb06b498c050d2f4e32f90a7a8b" +dependencies = [ + "nu-ansi-term", + "serde", + "serde_json", + "sharded-slab", + "smallvec", + "thread_local", + "tracing-core", + "tracing-log", + "tracing-serde", ] [[package]] @@ -4227,6 +4279,12 @@ dependencies = [ "rand", ] +[[package]] +name = "valuable" +version = "0.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "830b7e5d4d90034032940e4ace0d9a9a057e7a45cd94e6c007832e39edb82f6d" + [[package]] name = "value-bag" version = "1.8.1" diff --git a/Cargo.toml b/Cargo.toml index ef0c39d4..fe612c38 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -44,12 +44,10 @@ config = "0" crossbeam-skiplist = "0.1" dashmap = "5.5.3" derive_more = "0" -fern = "0" futures = "0" hex-literal = "0" hyper = "1" lazy_static = "1" -log = { version = "0", features = ["release_max_level_info"] } multimap = "0" percent-encoding = "2" r2d2 = "0" @@ -72,13 +70,13 @@ torrust-tracker-located-error = { version = "3.0.0-alpha.12-develop", path = "pa torrust-tracker-primitives = { version = "3.0.0-alpha.12-develop", path = "packages/primitives" } torrust-tracker-torrent-repository = { version = "3.0.0-alpha.12-develop", path = "packages/torrent-repository" } tower-http = { version = "0", features = ["compression-full", "cors", "propagate-header", "request-id", "trace"] } -trace = "0" tracing = "0" +tracing-subscriber = { version = "0", features = ["json"] } url = "2" uuid = { version = "1", features = ["v4"] } [package.metadata.cargo-machete] -ignored = ["serde_bytes", "crossbeam-skiplist", "dashmap"] +ignored = ["crossbeam-skiplist", "dashmap", "serde_bytes"] [dev-dependencies] local-ip-address = "0" @@ -92,7 +90,7 @@ members = [ "packages/located-error", "packages/primitives", "packages/test-helpers", - "packages/torrent-repository" + "packages/torrent-repository", ] [profile.dev] @@ -106,5 +104,5 @@ lto = "fat" opt-level = 3 [profile.release-debug] -inherits = "release" debug = true +inherits = "release" diff --git a/docs/benchmarking.md b/docs/benchmarking.md index 7c82df14..9d3f854c 100644 --- a/docs/benchmarking.md +++ b/docs/benchmarking.md @@ -29,7 +29,7 @@ cargo build --release -p aquatic_udp_load_test Run the tracker with UDP service enabled and other services disabled and set log level to `error`. ```toml -log_level = "error" +trace_level = "error" [[udp_trackers]] enabled = true @@ -55,7 +55,7 @@ Output: ```output Starting client with config: Config { server_address: 127.0.0.1:6969, - log_level: Error, + trace_level: Error, workers: 1, duration: 0, summarize_last: 0, @@ -163,7 +163,7 @@ Announce responses per info hash: Run the tracker with UDP service enabled and other services disabled and set log level to `error`. ```toml -log_level = "error" +trace_level = "error" [[udp_trackers]] enabled = true diff --git a/packages/configuration/src/lib.rs b/packages/configuration/src/lib.rs index ca873f3c..5e3ceac7 100644 --- a/packages/configuration/src/lib.rs +++ b/packages/configuration/src/lib.rs @@ -144,8 +144,8 @@ //! RequestHeader set X-Forwarded-Proto "https" //! RequestHeader set X-Forwarded-Port "443" //! -//! ErrorLog ${APACHE_LOG_DIR}/tracker.torrust.com-error.log -//! CustomLog ${APACHE_LOG_DIR}/tracker.torrust.com-access.log combined +//! ErrorLog ${APACHE_LOG_DIR}/tracker.torrust.com-error.tracing +//! CustomLog ${APACHE_LOG_DIR}/tracker.torrust.com-access.tracing combined //! //! SSLCertificateFile CERT_PATH //! SSLCertificateKeyFile CERT_KEY_PATH @@ -196,7 +196,7 @@ //! db_path = "./storage/tracker/lib/database/sqlite3.db" //! external_ip = "0.0.0.0" //! inactive_peer_cleanup_interval = 600 -//! log_level = "info" +//! trace_filter = "info" //! max_peer_timeout = 900 //! min_announce_interval = 120 //! mode = "public" @@ -236,7 +236,7 @@ use std::sync::Arc; use std::{env, fs}; use config::{Config, ConfigError, File, FileFormat}; -use derive_more::Constructor; +use derive_more::{AsRef, Constructor}; use serde::{Deserialize, Serialize}; use serde_with::{serde_as, NoneAsEmptyString}; use thiserror::Error; @@ -431,13 +431,90 @@ impl Default for AnnouncePolicy { } } +#[derive(Serialize, Deserialize, PartialEq, Eq, Debug, AsRef)] +#[serde(transparent)] +pub struct TraceLevel { + level: String, +} + +impl TraceLevel { + #[must_use] + pub fn new(level: &str) -> Self { + Self { + level: level.to_ascii_lowercase().to_string(), + } + } +} + +impl std::fmt::Display for TraceLevel { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + f.write_str(&self.level.to_ascii_lowercase()) + } +} + +impl Default for TraceLevel { + fn default() -> Self { + Self::new("info") + } +} + +#[derive(Serialize, Deserialize, PartialEq, Eq, Debug, AsRef)] +#[serde(transparent)] +pub struct TraceStyle { + style: String, +} + +impl TraceStyle { + #[must_use] + pub fn new(style: &str) -> Self { + Self { + style: style.to_ascii_lowercase().to_string(), + } + } +} + +impl std::fmt::Display for TraceStyle { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + f.write_str(&self.style.to_ascii_lowercase()) + } +} + +impl Default for TraceStyle { + fn default() -> Self { + Self::new("pretty") + } +} + /// Core configuration for the tracker. #[allow(clippy::struct_excessive_bools)] #[derive(Serialize, Deserialize, PartialEq, Eq, Debug)] pub struct Configuration { - /// Logging level. Possible values are: `Off`, `Error`, `Warn`, `Info`, - /// `Debug` and `Trace`. Default is `Info`. - pub log_level: Option, + /// Maximum Verbosity Level for Trace Subscription. + /// + /// Possible values are: + /// - `off` + /// - `error` (strongest) + /// - `info` <--------- default + /// - `debug` + /// - `trace` (weakest) + /// + /// Default is `Info`. + #[serde(default, alias = "log_level", alias = "trace_filter")] + pub tracing_max_verbosity_level: TraceLevel, + + /// Trace Subscription Format and Style + /// + /// Possible values are: + /// - `full` + /// - `pretty` <------------- default + /// - `pretty_with_paths` + /// - `pretty_without_paths` + /// - `compact` + /// - `json` + /// + #[serde(default, alias = "trace_style")] + pub tracing_format_style: TraceStyle, + /// Tracker mode. See [`TrackerMode`] for more information. pub mode: TrackerMode, @@ -544,7 +621,8 @@ impl Default for Configuration { let announce_policy = AnnouncePolicy::default(); let mut configuration = Configuration { - log_level: Option::from(String::from("info")), + tracing_max_verbosity_level: TraceLevel::default(), + tracing_format_style: TraceStyle::new("pretty"), mode: TrackerMode::Public, db_driver: DatabaseDriver::Sqlite3, db_path: String::from("./storage/tracker/lib/database/sqlite3.db"), @@ -686,7 +764,8 @@ mod tests { #[cfg(test)] fn default_config_toml() -> String { - let config = r#"log_level = "info" + let config = r#"tracing_max_verbosity_level = "info" + tracing_format_style = "pretty" mode = "public" db_driver = "Sqlite3" db_path = "./storage/tracker/lib/database/sqlite3.db" diff --git a/packages/located-error/Cargo.toml b/packages/located-error/Cargo.toml index fa3d1d76..637ea305 100644 --- a/packages/located-error/Cargo.toml +++ b/packages/located-error/Cargo.toml @@ -15,7 +15,7 @@ rust-version.workspace = true version.workspace = true [dependencies] -log = { version = "0", features = ["release_max_level_info"] } +tracing = "0" [dev-dependencies] thiserror = "1" diff --git a/packages/located-error/src/lib.rs b/packages/located-error/src/lib.rs index 49e13560..bfd4d4a8 100644 --- a/packages/located-error/src/lib.rs +++ b/packages/located-error/src/lib.rs @@ -33,7 +33,7 @@ use std::error::Error; use std::panic::Location; use std::sync::Arc; -use log::debug; +use tracing::debug; pub type DynError = Arc; diff --git a/packages/test-helpers/src/configuration.rs b/packages/test-helpers/src/configuration.rs index 49cfdd39..7116da22 100644 --- a/packages/test-helpers/src/configuration.rs +++ b/packages/test-helpers/src/configuration.rs @@ -2,7 +2,7 @@ use std::env; use std::net::IpAddr; -use torrust_tracker_configuration::Configuration; +use torrust_tracker_configuration::{Configuration, TraceLevel}; use torrust_tracker_primitives::TrackerMode; use crate::random; @@ -15,7 +15,7 @@ use crate::random; /// > **NOTICE**: Port 0 is used for ephemeral ports, which means that the OS /// will assign a random free port for the tracker to use. /// -/// > **NOTICE**: You can change the log level to `debug` to see the logs of the +/// > **NOTICE**: You can change the tracing level to `debug` to see the traces of the /// tracker while running the tests. That can be particularly useful when /// debugging tests. /// @@ -28,7 +28,7 @@ pub fn ephemeral() -> Configuration { // For example: a test for the UDP tracker should disable the API and HTTP tracker. let mut config = Configuration { - log_level: Some("off".to_owned()), // Change to `debug` for tests debugging + tracing_max_verbosity_level: TraceLevel::new("off"), // Change to `debug` for tests debugging ..Default::default() }; diff --git a/share/default/config/tracker.container.mysql.toml b/share/default/config/tracker.container.mysql.toml index e7714c22..6d51486c 100644 --- a/share/default/config/tracker.container.mysql.toml +++ b/share/default/config/tracker.container.mysql.toml @@ -3,7 +3,8 @@ db_driver = "MySQL" db_path = "mysql://db_user:db_user_secret_password@mysql:3306/torrust_tracker" external_ip = "0.0.0.0" inactive_peer_cleanup_interval = 600 -log_level = "info" +trace_filter = "info" +trace_style = "full" max_peer_timeout = 900 min_announce_interval = 120 mode = "public" diff --git a/share/default/config/tracker.container.sqlite3.toml b/share/default/config/tracker.container.sqlite3.toml index 4ec055c5..ea3f5844 100644 --- a/share/default/config/tracker.container.sqlite3.toml +++ b/share/default/config/tracker.container.sqlite3.toml @@ -3,7 +3,8 @@ db_driver = "Sqlite3" db_path = "/var/lib/torrust/tracker/database/sqlite3.db" external_ip = "0.0.0.0" inactive_peer_cleanup_interval = 600 -log_level = "info" +trace_filter = "info" +trace_style = "full" max_peer_timeout = 900 min_announce_interval = 120 mode = "public" diff --git a/share/default/config/tracker.development.sqlite3.toml b/share/default/config/tracker.development.sqlite3.toml index 9304a2d5..a6647a5c 100644 --- a/share/default/config/tracker.development.sqlite3.toml +++ b/share/default/config/tracker.development.sqlite3.toml @@ -3,7 +3,8 @@ db_driver = "Sqlite3" db_path = "./storage/tracker/lib/database/sqlite3.db" external_ip = "0.0.0.0" inactive_peer_cleanup_interval = 600 -log_level = "info" +trace_filter = "debug" +trace_style = "pretty_with_paths" max_peer_timeout = 900 min_announce_interval = 120 mode = "public" diff --git a/share/default/config/tracker.e2e.container.sqlite3.toml b/share/default/config/tracker.e2e.container.sqlite3.toml index 86ffb3ff..6995a5e6 100644 --- a/share/default/config/tracker.e2e.container.sqlite3.toml +++ b/share/default/config/tracker.e2e.container.sqlite3.toml @@ -3,7 +3,8 @@ db_driver = "Sqlite3" db_path = "/var/lib/torrust/tracker/database/sqlite3.db" external_ip = "0.0.0.0" inactive_peer_cleanup_interval = 600 -log_level = "info" +trace_filter = "info" +trace_style = "full" max_peer_timeout = 900 min_announce_interval = 120 mode = "public" diff --git a/share/default/config/tracker.udp.benchmarking.toml b/share/default/config/tracker.udp.benchmarking.toml index 70298e9d..ce56c6f9 100644 --- a/share/default/config/tracker.udp.benchmarking.toml +++ b/share/default/config/tracker.udp.benchmarking.toml @@ -3,7 +3,7 @@ db_driver = "Sqlite3" db_path = "./storage/tracker/lib/database/sqlite3.db" external_ip = "0.0.0.0" inactive_peer_cleanup_interval = 600 -log_level = "error" +trace_filter = "error" max_peer_timeout = 900 min_announce_interval = 120 mode = "public" diff --git a/src/app.rs b/src/app.rs index 8bdc281a..d5eefeb8 100644 --- a/src/app.rs +++ b/src/app.rs @@ -23,9 +23,9 @@ //! - Tracker REST API: the tracker API can be enabled/disabled. use std::sync::Arc; -use log::warn; use tokio::task::JoinHandle; use torrust_tracker_configuration::Configuration; +use tracing::warn; use crate::bootstrap::jobs::{health_check_api, http_tracker, torrent_cleanup, tracker_apis, udp_tracker}; use crate::servers::registar::Registar; diff --git a/src/bootstrap/app.rs b/src/bootstrap/app.rs index 396e6368..1edd7459 100644 --- a/src/bootstrap/app.rs +++ b/src/bootstrap/app.rs @@ -9,7 +9,7 @@ //! //! 1. Load the global application configuration. //! 2. Initialize static variables. -//! 3. Initialize logging. +//! 3. Initialize the tracing subscriber. //! 4. Initialize the domain tracker. use std::sync::Arc; @@ -37,7 +37,7 @@ pub fn setup() -> (Configuration, Arc) { #[must_use] pub fn initialize_with_configuration(configuration: &Configuration) -> Arc { initialize_static(); - initialize_logging(configuration); + initialize_tracing(configuration); Arc::new(initialize_tracker(configuration)) } @@ -64,9 +64,9 @@ pub fn initialize_tracker(config: &Configuration) -> Tracker { tracker_factory(config) } -/// It initializes the log level, format and channel. +/// It initializes the tracing level, format and channel. /// -/// See [the logging setup](crate::bootstrap::logging::setup) for more info about logging. -pub fn initialize_logging(config: &Configuration) { - bootstrap::logging::setup(config); +/// See [the tracing setup](crate::bootstrap::tracing::setup) for more info about tracing. +pub fn initialize_tracing(config: &Configuration) { + bootstrap::tracing::setup(config); } diff --git a/src/bootstrap/jobs/health_check_api.rs b/src/bootstrap/jobs/health_check_api.rs index eec4d81a..55804c75 100644 --- a/src/bootstrap/jobs/health_check_api.rs +++ b/src/bootstrap/jobs/health_check_api.rs @@ -14,10 +14,10 @@ //! Refer to the [configuration documentation](https://docs.rs/torrust-tracker-configuration) //! for the API configuration options. -use log::info; use tokio::sync::oneshot; use tokio::task::JoinHandle; use torrust_tracker_configuration::HealthCheckApi; +use tracing::info; use super::Started; use crate::servers::health_check_api::server; diff --git a/src/bootstrap/jobs/http_tracker.rs b/src/bootstrap/jobs/http_tracker.rs index 0a0638b7..88b38b13 100644 --- a/src/bootstrap/jobs/http_tracker.rs +++ b/src/bootstrap/jobs/http_tracker.rs @@ -14,9 +14,9 @@ use std::net::SocketAddr; use std::sync::Arc; use axum_server::tls_rustls::RustlsConfig; -use log::info; use tokio::task::JoinHandle; use torrust_tracker_configuration::HttpTracker; +use tracing::info; use super::make_rust_tls; use crate::core; diff --git a/src/bootstrap/jobs/mod.rs b/src/bootstrap/jobs/mod.rs index 2c12eb40..a9d0d58e 100644 --- a/src/bootstrap/jobs/mod.rs +++ b/src/bootstrap/jobs/mod.rs @@ -77,9 +77,9 @@ use std::panic::Location; use std::sync::Arc; use axum_server::tls_rustls::RustlsConfig; -use log::info; use thiserror::Error; use torrust_tracker_located_error::{DynError, LocatedError}; +use tracing::info; /// Error returned by the Bootstrap Process. #[derive(Error, Debug)] diff --git a/src/bootstrap/jobs/torrent_cleanup.rs b/src/bootstrap/jobs/torrent_cleanup.rs index 30081343..e707a2c7 100644 --- a/src/bootstrap/jobs/torrent_cleanup.rs +++ b/src/bootstrap/jobs/torrent_cleanup.rs @@ -13,9 +13,9 @@ use std::sync::Arc; use chrono::Utc; -use log::info; use tokio::task::JoinHandle; use torrust_tracker_configuration::Configuration; +use tracing::info; use crate::core; diff --git a/src/bootstrap/jobs/tracker_apis.rs b/src/bootstrap/jobs/tracker_apis.rs index ffd7c740..b9c6cbb6 100644 --- a/src/bootstrap/jobs/tracker_apis.rs +++ b/src/bootstrap/jobs/tracker_apis.rs @@ -24,9 +24,9 @@ use std::net::SocketAddr; use std::sync::Arc; use axum_server::tls_rustls::RustlsConfig; -use log::info; use tokio::task::JoinHandle; use torrust_tracker_configuration::{AccessTokens, HttpApi}; +use tracing::info; use super::make_rust_tls; use crate::core; diff --git a/src/bootstrap/jobs/udp_tracker.rs b/src/bootstrap/jobs/udp_tracker.rs index e9e4bc64..c79382a4 100644 --- a/src/bootstrap/jobs/udp_tracker.rs +++ b/src/bootstrap/jobs/udp_tracker.rs @@ -8,9 +8,9 @@ //! for the configuration options. use std::sync::Arc; -use log::debug; use tokio::task::JoinHandle; use torrust_tracker_configuration::UdpTracker; +use tracing::debug; use crate::core; use crate::servers::registar::ServiceRegistrationForm; diff --git a/src/bootstrap/logging.rs b/src/bootstrap/logging.rs deleted file mode 100644 index 97e26919..00000000 --- a/src/bootstrap/logging.rs +++ /dev/null @@ -1,60 +0,0 @@ -//! Setup for the application logging. -//! -//! It redirects the log info to the standard output with the log level defined in the configuration. -//! -//! - `Off` -//! - `Error` -//! - `Warn` -//! - `Info` -//! - `Debug` -//! - `Trace` -//! -//! Refer to the [configuration crate documentation](https://docs.rs/torrust-tracker-configuration) to know how to change log settings. -use std::str::FromStr; -use std::sync::Once; - -use log::{info, LevelFilter}; -use torrust_tracker_configuration::Configuration; - -static INIT: Once = Once::new(); - -/// It redirects the log info to the standard output with the log level defined in the configuration -pub fn setup(cfg: &Configuration) { - let level = config_level_or_default(&cfg.log_level); - - if level == log::LevelFilter::Off { - return; - } - - INIT.call_once(|| { - stdout_config(level); - }); -} - -fn config_level_or_default(log_level: &Option) -> LevelFilter { - match log_level { - None => log::LevelFilter::Info, - Some(level) => LevelFilter::from_str(level).unwrap(), - } -} - -fn stdout_config(level: LevelFilter) { - if let Err(_err) = fern::Dispatch::new() - .format(|out, message, record| { - out.finish(format_args!( - "{} [{}][{}] {}", - chrono::Local::now().format("%+"), - record.target(), - record.level(), - message - )); - }) - .level(level) - .chain(std::io::stdout()) - .apply() - { - panic!("Failed to initialize logging.") - } - - info!("logging initialized."); -} diff --git a/src/bootstrap/mod.rs b/src/bootstrap/mod.rs index 22044aaf..d7e7cc00 100644 --- a/src/bootstrap/mod.rs +++ b/src/bootstrap/mod.rs @@ -8,4 +8,4 @@ pub mod app; pub mod config; pub mod jobs; -pub mod logging; +pub mod tracing; diff --git a/src/bootstrap/tracing.rs b/src/bootstrap/tracing.rs new file mode 100644 index 00000000..57cbffb1 --- /dev/null +++ b/src/bootstrap/tracing.rs @@ -0,0 +1,131 @@ +//! Setup for the application tracing. +//! +//! It redirects the tracing info to the standard output with the tracing level defined in the configuration. +//! +//! (case is ignored) +//! +//! - `Off` (i.e. don't load any subscriber...) +//! - `Error` +//! - `Warn` +//! - `Info` +//! - `Debug` +//! - `Trace` +//! +//! Refer to the [configuration crate documentation](https://docs.rs/torrust-tracker-configuration) to know how to change tracing settings. +use std::sync::Once; + +use torrust_tracker_configuration::{Configuration, TraceLevel}; +use tracing::debug; +use tracing::level_filters::LevelFilter; + +static INIT: Once = Once::new(); + +#[derive(Debug)] +enum TraceStyle { + Default, + Pretty(bool), + Compact, + Json, +} + +impl TraceStyle { + fn new(style: &torrust_tracker_configuration::TraceStyle, filter: LevelFilter) -> Self { + match style.to_string().as_str() { + "full" => Self::Default, + "pretty" => { + // TRACE < DEBUG < INFO < ERROR < OFF + let default = LevelFilter::DEBUG <= filter; + Self::Pretty(default) + } + "pretty_with_paths" => Self::Pretty(true), + "pretty_without_paths" => Self::Pretty(false), + "compact" => Self::Compact, + "json" => Self::Json, + + _ => panic!( + " +Error! Unrecognized `trace_style`! + + Found: \"{filter}\" + +But, the possible values are: + - `full` + (default) ---> - `pretty` + - `pretty_with_paths` + - `pretty_without_paths` + - `compact` + - `json` +" + ), + } + } +} + +impl std::fmt::Display for TraceStyle { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + let style = match self { + TraceStyle::Default => "Default Style", + TraceStyle::Pretty(path) => match path { + true => "Pretty Style with File Paths", + false => "Pretty Style without File Paths", + }, + + TraceStyle::Compact => "Compact Style", + TraceStyle::Json => "Json Format", + }; + + f.write_str(style) + } +} + +/// It redirects the tracing info to the standard output with the tracing level defined in the configuration +pub fn setup(cfg: &Configuration) { + let filter = get_level_filter(&cfg.tracing_max_verbosity_level); + let style = TraceStyle::new(&cfg.tracing_format_style, filter); + + if filter == LevelFilter::OFF { + return; + } + + INIT.call_once(|| { + stdout_init(filter, &style); + }); +} + +/// Gets the [`LevelFilter`] from the String in [`TraceLevel`]. +/// +/// # Panics +/// +/// If the string cannot be parsed into a valid filter level. +/// +fn get_level_filter(filter: &TraceLevel) -> LevelFilter { + filter.to_string().parse().unwrap_or_else(|_| { + panic!( + " +Error! Unrecognized `log_level` (or alias) `trace_filter`! + + Found: \"{filter}\" + +But, the possible values are: + - `off` + - `error` (strongest) + (default) ---> - `info` + - `debug` + - `trace` (weakest) +" + ) + }) +} + +fn stdout_init(filter: LevelFilter, style: &TraceStyle) { + let builder = tracing_subscriber::fmt().with_max_level(filter); + + let () = match style { + TraceStyle::Default => builder.init(), + TraceStyle::Pretty(display_filename) => builder.pretty().with_file(*display_filename).init(), + TraceStyle::Compact => builder.compact().init(), + TraceStyle::Json => builder.json().init(), + }; + + debug!("tracing initialized."); +} diff --git a/src/console/ci/e2e/docker.rs b/src/console/ci/e2e/docker.rs index c024efba..0a3a1b7b 100644 --- a/src/console/ci/e2e/docker.rs +++ b/src/console/ci/e2e/docker.rs @@ -4,7 +4,7 @@ use std::process::{Command, Output}; use std::thread::sleep; use std::time::{Duration, Instant}; -use log::{debug, info}; +use tracing::{debug, info}; /// Docker command wrapper. pub struct Docker {} @@ -143,12 +143,12 @@ impl Docker { } } - /// Fetches logs from a Docker container. + /// Fetches traces from a Docker container. /// /// # Errors /// - /// Will fail if the docker logs command fails. - pub fn logs(container: &str) -> io::Result { + /// Will fail if the docker traces command fails. + pub fn traces(container: &str) -> io::Result { let output = Command::new("docker").args(["logs", container]).output()?; if output.status.success() { @@ -156,7 +156,7 @@ impl Docker { } else { Err(io::Error::new( io::ErrorKind::Other, - format!("Failed to fetch logs from Docker container {container}"), + format!("Failed to fetch traces from Docker container {container}"), )) } } diff --git a/src/console/ci/e2e/logs_parser.rs b/src/console/ci/e2e/logs_parser.rs deleted file mode 100644 index 6d334919..00000000 --- a/src/console/ci/e2e/logs_parser.rs +++ /dev/null @@ -1,114 +0,0 @@ -//! Utilities to parse Torrust Tracker logs. -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: "; - -#[derive(Serialize, Deserialize, Debug, Default)] -pub struct RunningServices { - pub udp_trackers: Vec, - pub http_trackers: Vec, - pub health_checks: Vec, -} - -impl RunningServices { - /// It parses the tracker logs to extract the running services. - /// - /// For example, from this logs: - /// - /// ```text - /// Loading default configuration file: `./share/default/config/tracker.development.sqlite3.toml` ... - /// 2024-01-24T16:36:14.614898789+00:00 [torrust_tracker::bootstrap::logging][INFO] logging initialized. - /// 2024-01-24T16:36:14.615586025+00:00 [UDP TRACKER][INFO] Starting on: udp://0.0.0.0:6969 - /// 2024-01-24T16:36:14.615623705+00:00 [torrust_tracker::bootstrap::jobs][INFO] TLS not enabled - /// 2024-01-24T16:36:14.615694484+00:00 [HTTP TRACKER][INFO] Starting on: http://0.0.0.0:7070 - /// 2024-01-24T16:36:14.615710534+00:00 [HTTP TRACKER][INFO] Started on: http://0.0.0.0:7070 - /// 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 - /// ``` - /// - /// It would extract these services: - /// - /// ```json - /// { - /// "udp_trackers": [ - /// "127.0.0.1:6969" - /// ], - /// "http_trackers": [ - /// "http://127.0.0.1:7070" - /// ], - /// "health_checks": [ - /// "http://127.0.0.1:1313/health_check" - /// ] - /// } - /// ``` - #[must_use] - pub fn parse_from_logs(logs: &str) -> Self { - let mut udp_trackers: Vec = Vec::new(); - let mut http_trackers: Vec = Vec::new(); - let mut health_checks: Vec = Vec::new(); - - for line in logs.lines() { - if let Some(address) = Self::extract_address_if_matches(line, UDP_TRACKER_PATTERN) { - udp_trackers.push(address); - } else if let Some(address) = Self::extract_address_if_matches(line, HTTP_TRACKER_PATTERN) { - http_trackers.push(address); - } else if let Some(address) = Self::extract_address_if_matches(line, HEALTH_CHECK_PATTERN) { - health_checks.push(format!("{address}/health_check")); - } - } - - Self { - udp_trackers, - http_trackers, - health_checks, - } - } - - fn extract_address_if_matches(line: &str, pattern: &str) -> Option { - line.find(pattern) - .map(|start| Self::replace_wildcard_ip_with_localhost(line[start + pattern.len()..].trim())) - } - - fn replace_wildcard_ip_with_localhost(address: &str) -> String { - address.replace("0.0.0.0", "127.0.0.1") - } -} - -#[cfg(test)] -mod tests { - use super::*; - - #[test] - fn it_should_parse_from_logs_with_valid_logs() { - 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"; - let running_services = RunningServices::parse_from_logs(logs); - - 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"]); - } - - #[test] - fn it_should_ignore_logs_with_no_matching_lines() { - let logs = "[Other Service][INFO] Starting on: 0.0.0.0:7070"; - let running_services = RunningServices::parse_from_logs(logs); - - assert!(running_services.udp_trackers.is_empty()); - assert!(running_services.http_trackers.is_empty()); - assert!(running_services.health_checks.is_empty()); - } - - #[test] - fn it_should_replace_wildcard_ip_with_localhost() { - let address = "0.0.0.0:8080"; - assert_eq!(RunningServices::replace_wildcard_ip_with_localhost(address), "127.0.0.1:8080"); - } -} diff --git a/src/console/ci/e2e/mod.rs b/src/console/ci/e2e/mod.rs index 58a876cb..ce651d51 100644 --- a/src/console/ci/e2e/mod.rs +++ b/src/console/ci/e2e/mod.rs @@ -1,6 +1,6 @@ //! E2E tests scripts. pub mod docker; -pub mod logs_parser; pub mod runner; +pub mod trace_parser; pub mod tracker_checker; pub mod tracker_container; diff --git a/src/console/ci/e2e/runner.rs b/src/console/ci/e2e/runner.rs index 1a474680..83cf6146 100644 --- a/src/console/ci/e2e/runner.rs +++ b/src/console/ci/e2e/runner.rs @@ -3,11 +3,11 @@ //! ```text //! cargo run --bin e2e_tests_runner share/default/config/tracker.e2e.container.sqlite3.toml //! ``` -use log::{debug, info, LevelFilter}; +use tracing::{debug, info, Level}; use super::tracker_container::TrackerContainer; use crate::console::ci::e2e::docker::RunOptions; -use crate::console::ci::e2e::logs_parser::RunningServices; +use crate::console::ci::e2e::trace_parser::RunningServices; use crate::console::ci::e2e::tracker_checker::{self}; /* code-review: @@ -32,7 +32,7 @@ pub struct Arguments { /// /// Will panic if it can't not perform any of the operations. pub fn run() { - setup_runner_logging(LevelFilter::Info); + setup_runner_tracing(Level::INFO); let args = parse_arguments(); @@ -76,25 +76,10 @@ pub fn run() { info!("Tracker container final state:\n{:#?}", tracker_container); } -fn setup_runner_logging(level: LevelFilter) { - if let Err(_err) = fern::Dispatch::new() - .format(|out, message, record| { - out.finish(format_args!( - "{} [{}][{}] {}", - chrono::Local::now().format("%+"), - record.target(), - record.level(), - message - )); - }) - .level(level) - .chain(std::io::stdout()) - .apply() - { - panic!("Failed to initialize logging.") - } +fn setup_runner_tracing(level: Level) { + let () = tracing_subscriber::fmt().pretty().with_max_level(level).init(); - debug!("logging initialized."); + debug!("tracing initialized."); } fn parse_arguments() -> Arguments { diff --git a/src/console/ci/e2e/trace_parser.rs b/src/console/ci/e2e/trace_parser.rs new file mode 100644 index 00000000..56a483a5 --- /dev/null +++ b/src/console/ci/e2e/trace_parser.rs @@ -0,0 +1,115 @@ +//! Utilities to parse Torrust Tracker traces. +use serde::{Deserialize, Serialize}; + +const UDP_TRACKER_PATTERN: &str = "UDP TRACKER: Starting on: udp://"; +const HTTP_TRACKER_PATTERN: &str = "HTTP TRACKER: Starting on: "; +const HEALTH_CHECK_PATTERN: &str = "HEALTH CHECK API: Starting on: "; + +#[derive(Serialize, Deserialize, Debug, Default)] +pub struct RunningServices { + pub udp_trackers: Vec, + pub http_trackers: Vec, + pub health_checks: Vec, +} + +impl RunningServices { + /// It parses the tracker traces to extract the running services. + /// + /// For example, from this traces: + /// + /// ```text + /// Loading configuration file: `./storage/tracker/etc/tracker.toml` ... + /// 2024-04-10T02:28:58.219529Z INFO UDP TRACKER: Starting on: udp://0.0.0.0:6969 + /// 2024-04-10T02:28:58.219563Z INFO torrust_tracker::servers::udp::server: Running UDP Tracker on Socket: 0.0.0.0:6969 + /// 2024-04-10T02:28:58.219578Z INFO torrust_tracker::bootstrap::jobs: TLS not enabled + /// 2024-04-10T02:28:58.219612Z INFO HTTP TRACKER: Starting on: http://0.0.0.0:7070 + /// 2024-04-10T02:28:58.219775Z INFO HTTP TRACKER: Started on: http://0.0.0.0:7070 + /// 2024-04-10T02:28:58.219787Z INFO torrust_tracker::bootstrap::jobs: TLS not enabled + /// 2024-04-10T02:28:58.219929Z INFO API: Starting on http://127.0.0.1:1212 + /// 2024-04-10T02:28:58.219936Z INFO API: Started on http://127.0.0.1:1212 + /// 2024-04-10T02:28:58.219967Z INFO HEALTH CHECK API: Starting on: http://127.0.0.1:1313 + /// 2024-04-10T02:28:58.220019Z INFO HEALTH CHECK API: Started on: http://127.0.0.1:1313 + /// ``` + /// + /// It would extract these services: + /// + /// ```json + /// { + /// "udp_trackers": [ + /// "127.0.0.1:6969" + /// ], + /// "http_trackers": [ + /// "http://127.0.0.1:7070" + /// ], + /// "health_checks": [ + /// "http://127.0.0.1:1313/health_check" + /// ] + /// } + /// ``` + #[must_use] + pub fn parse_from_traces(traces: &str) -> Self { + let mut udp_trackers: Vec = Vec::new(); + let mut http_trackers: Vec = Vec::new(); + let mut health_checks: Vec = Vec::new(); + + for line in traces.lines() { + if let Some(address) = Self::extract_address_if_matches(line, UDP_TRACKER_PATTERN) { + udp_trackers.push(address); + } else if let Some(address) = Self::extract_address_if_matches(line, HTTP_TRACKER_PATTERN) { + http_trackers.push(address); + } else if let Some(address) = Self::extract_address_if_matches(line, HEALTH_CHECK_PATTERN) { + health_checks.push(format!("{address}/health_check")); + } + } + + Self { + udp_trackers, + http_trackers, + health_checks, + } + } + + fn extract_address_if_matches(line: &str, pattern: &str) -> Option { + line.find(pattern) + .map(|start| Self::replace_wildcard_ip_with_localhost(line[start + pattern.len()..].trim())) + } + + fn replace_wildcard_ip_with_localhost(address: &str) -> String { + address.replace("0.0.0.0", "127.0.0.1") + } +} + +#[cfg(test)] +mod tests { + use super::*; + + #[test] + fn it_should_parse_from_traces_with_valid_traces() { + let traces = "\ + 2024-04-10T02:28:58.219529Z INFO UDP TRACKER: Starting on: udp://0.0.0.0:6969\n\ + 2024-04-10T02:28:58.219612Z INFO HTTP TRACKER: Starting on: https://0.0.0.0:7070\n\ + 2024-04-10T02:28:58.219929Z INFO API: Starting on http://127.0.0.1:1212\n\ + 2024-04-10T02:28:58.219967Z INFO HEALTH CHECK API: Starting on: http://127.0.0.1:1313"; + let running_services = RunningServices::parse_from_traces(traces); + + assert_eq!(running_services.udp_trackers, vec!["127.0.0.1:6969"]); + assert_eq!(running_services.http_trackers, vec!["https://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_traces_with_no_matching_lines() { + let traces = "2024-04-10T02:28:58.219967Z INFO OTHER SERVICE: Starting on: http://127.0.0.1:1313"; + let running_services = RunningServices::parse_from_traces(traces); + + assert!(running_services.udp_trackers.is_empty()); + assert!(running_services.http_trackers.is_empty()); + assert!(running_services.health_checks.is_empty()); + } + + #[test] + fn it_should_replace_wildcard_ip_with_localhost() { + let address = "0.0.0.0:8080"; + assert_eq!(RunningServices::replace_wildcard_ip_with_localhost(address), "127.0.0.1:8080"); + } +} diff --git a/src/console/ci/e2e/tracker_checker.rs b/src/console/ci/e2e/tracker_checker.rs index edc67980..b2fd7df2 100644 --- a/src/console/ci/e2e/tracker_checker.rs +++ b/src/console/ci/e2e/tracker_checker.rs @@ -1,7 +1,7 @@ use std::io; use std::process::Command; -use log::info; +use tracing::info; /// Runs the Tracker Checker. /// diff --git a/src/console/ci/e2e/tracker_container.rs b/src/console/ci/e2e/tracker_container.rs index 5a4d11d0..5f1e0416 100644 --- a/src/console/ci/e2e/tracker_container.rs +++ b/src/console/ci/e2e/tracker_container.rs @@ -1,11 +1,11 @@ use std::time::Duration; -use log::{debug, error, info}; use rand::distributions::Alphanumeric; use rand::Rng; +use tracing::{debug, error, info}; use super::docker::{RunOptions, RunningContainer}; -use super::logs_parser::RunningServices; +use super::trace_parser::RunningServices; use crate::console::ci::e2e::docker::Docker; #[derive(Debug)] @@ -62,19 +62,19 @@ impl TrackerContainer { self.running = Some(container); - self.assert_there_are_no_panics_in_logs(); + self.assert_there_are_no_panics_in_traces(); } /// # Panics /// - /// Will panic if it can't get the logs from the running container. + /// Will panic if it can't get the traces from the running container. #[must_use] pub fn running_services(&self) -> RunningServices { - let logs = Docker::logs(&self.name).expect("Logs should be captured from running container"); + let traces = Docker::traces(&self.name).expect("Traces should be captured from running container"); - debug!("Parsing running services from logs. Logs :\n{logs}"); + debug!("Parsing running services from traces. Traces :\n{traces}"); - RunningServices::parse_from_logs(&logs) + RunningServices::parse_from_traces(&traces) } /// # Panics @@ -87,7 +87,7 @@ impl TrackerContainer { Docker::stop(container).expect("Container should be stopped"); - self.assert_there_are_no_panics_in_logs(); + self.assert_there_are_no_panics_in_traces(); } None => { if Docker::is_container_running(&self.name) { @@ -126,13 +126,13 @@ impl TrackerContainer { format!("{prefix}{rand_string}") } - fn assert_there_are_no_panics_in_logs(&self) { - let logs = Docker::logs(&self.name).expect("Logs should be captured from running container"); + fn assert_there_are_no_panics_in_traces(&self) { + let traces = Docker::traces(&self.name).expect("Traces should be captured from running container"); assert!( - !(logs.contains(" panicked at ") || logs.contains("RUST_BACKTRACE=1")), + !(traces.contains(" panicked at ") || traces.contains("RUST_BACKTRACE=1")), "{}", - format!("Panics found is logs:\n{logs}") + format!("Panics found is traces:\n{traces}") ); } } diff --git a/src/console/clients/checker/app.rs b/src/console/clients/checker/app.rs index 82ea800d..8b41161b 100644 --- a/src/console/clients/checker/app.rs +++ b/src/console/clients/checker/app.rs @@ -17,7 +17,7 @@ use std::sync::Arc; use anyhow::{Context, Result}; use clap::Parser; -use log::{debug, LevelFilter}; +use tracing::debug; use super::config::Configuration; use super::console::Console; @@ -40,7 +40,7 @@ struct Args { /// /// Will return an error if the configuration was not provided. pub async fn run() -> Result> { - setup_logging(LevelFilter::Info); + setup_tracing(tracing::Level::INFO); let args = Args::parse(); @@ -56,25 +56,10 @@ pub async fn run() -> Result> { Ok(service.run_checks().await) } -fn setup_logging(level: LevelFilter) { - if let Err(_err) = fern::Dispatch::new() - .format(|out, message, record| { - out.finish(format_args!( - "{} [{}][{}] {}", - chrono::Local::now().format("%+"), - record.target(), - record.level(), - message - )); - }) - .level(level) - .chain(std::io::stdout()) - .apply() - { - panic!("Failed to initialize logging.") - } +fn setup_tracing(level: tracing::Level) { + let () = tracing_subscriber::fmt().pretty().with_max_level(level).init(); - debug!("logging initialized."); + debug!("tracing initialized."); } fn setup_config(args: Args) -> Result { diff --git a/src/console/clients/checker/checks/http.rs b/src/console/clients/checker/checks/http.rs index 501696df..81ec95a5 100644 --- a/src/console/clients/checker/checks/http.rs +++ b/src/console/clients/checker/checks/http.rs @@ -1,9 +1,9 @@ use std::str::FromStr; use colored::Colorize; -use log::debug; use reqwest::Url as ServiceUrl; use torrust_tracker_primitives::info_hash::InfoHash; +use tracing::debug; use url::Url; use crate::console::clients::checker::console::Console; diff --git a/src/console/clients/checker/checks/udp.rs b/src/console/clients/checker/checks/udp.rs index 47a2a1a0..9b57f353 100644 --- a/src/console/clients/checker/checks/udp.rs +++ b/src/console/clients/checker/checks/udp.rs @@ -3,8 +3,8 @@ use std::net::SocketAddr; use aquatic_udp_protocol::{Port, TransactionId}; use colored::Colorize; use hex_literal::hex; -use log::debug; use torrust_tracker_primitives::info_hash::InfoHash; +use tracing::debug; use crate::console::clients::checker::console::Console; use crate::console::clients::checker::printer::Printer; diff --git a/src/console/clients/checker/logger.rs b/src/console/clients/checker/logger.rs index 50e97189..944a3275 100644 --- a/src/console/clients/checker/logger.rs +++ b/src/console/clients/checker/logger.rs @@ -2,17 +2,17 @@ use std::cell::RefCell; use super::printer::{Printer, CLEAR_SCREEN}; -pub struct Logger { +pub struct Tracer { output: RefCell, } -impl Default for Logger { +impl Default for Tracer { fn default() -> Self { Self::new() } } -impl Logger { +impl Tracer { #[must_use] pub fn new() -> Self { Self { @@ -20,12 +20,12 @@ impl Logger { } } - pub fn log(&self) -> String { + pub fn tracing(&self) -> String { self.output.borrow().clone() } } -impl Printer for Logger { +impl Printer for Tracer { fn clear(&self) { self.print(CLEAR_SCREEN); } @@ -49,24 +49,24 @@ impl Printer for Logger { #[cfg(test)] mod tests { - use crate::console::clients::checker::logger::Logger; + use crate::console::clients::checker::logger::Tracer; use crate::console::clients::checker::printer::{Printer, CLEAR_SCREEN}; #[test] fn should_capture_the_clear_screen_command() { - let console_logger = Logger::new(); + let console_logger = Tracer::new(); console_logger.clear(); - assert_eq!(CLEAR_SCREEN, console_logger.log()); + assert_eq!(CLEAR_SCREEN, console_logger.tracing()); } #[test] fn should_capture_the_print_command_output() { - let console_logger = Logger::new(); + let console_logger = Tracer::new(); console_logger.print("OUTPUT"); - assert_eq!("OUTPUT", console_logger.log()); + assert_eq!("OUTPUT", console_logger.tracing()); } } diff --git a/src/console/clients/udp/app.rs b/src/console/clients/udp/app.rs index 540a25f3..aa87243c 100644 --- a/src/console/clients/udp/app.rs +++ b/src/console/clients/udp/app.rs @@ -63,8 +63,8 @@ use anyhow::Context; use aquatic_udp_protocol::Response::{self, AnnounceIpv4, AnnounceIpv6, Scrape}; use aquatic_udp_protocol::{Port, TransactionId}; use clap::{Parser, Subcommand}; -use log::{debug, LevelFilter}; use torrust_tracker_primitives::info_hash::InfoHash as TorrustInfoHash; +use tracing::debug; use url::Url; use crate::console::clients::udp::checker; @@ -102,7 +102,7 @@ enum Command { /// /// pub async fn run() -> anyhow::Result<()> { - setup_logging(LevelFilter::Info); + setup_tracing(tracing::Level::INFO); let args = Args::parse(); @@ -120,25 +120,10 @@ pub async fn run() -> anyhow::Result<()> { print_response(response) } -fn setup_logging(level: LevelFilter) { - if let Err(_err) = fern::Dispatch::new() - .format(|out, message, record| { - out.finish(format_args!( - "{} [{}][{}] {}", - chrono::Local::now().format("%+"), - record.target(), - record.level(), - message - )); - }) - .level(level) - .chain(std::io::stdout()) - .apply() - { - panic!("Failed to initialize logging.") - } +fn setup_tracing(level: tracing::Level) { + let () = tracing_subscriber::fmt().pretty().with_max_level(level).init(); - debug!("logging initialized."); + debug!("tracing initialized."); } async fn handle_announce(tracker_socket_addr: &SocketAddr, info_hash: &TorrustInfoHash) -> anyhow::Result { diff --git a/src/console/clients/udp/checker.rs b/src/console/clients/udp/checker.rs index 12b8d764..6eaf8e16 100644 --- a/src/console/clients/udp/checker.rs +++ b/src/console/clients/udp/checker.rs @@ -6,9 +6,9 @@ use aquatic_udp_protocol::{ AnnounceEvent, AnnounceRequest, ConnectRequest, ConnectionId, NumberOfBytes, NumberOfPeers, PeerId, PeerKey, Port, Response, ScrapeRequest, TransactionId, }; -use log::debug; use thiserror::Error; use torrust_tracker_primitives::info_hash::InfoHash as TorrustInfoHash; +use tracing::debug; use crate::shared::bit_torrent::tracker::udp::client::{UdpClient, UdpTrackerClient}; diff --git a/src/console/profiling.rs b/src/console/profiling.rs index e0867159..9e1fe8a9 100644 --- a/src/console/profiling.rs +++ b/src/console/profiling.rs @@ -81,7 +81,7 @@ //! ``` //! //! > NOTICE: We are using an specific tracker configuration for profiling that -//! removes all features except the UDP tracker and sets the logging level to `error`. +//! removes all features except the UDP tracker and sets the tracing level to `error`. //! //! Build the aquatic UDP load test command: //! @@ -107,7 +107,7 @@ //! ```text //! Starting client with config: Config { //! server_address: 127.0.0.1:6969, -//! log_level: Error, +//! trace_level: Error, //! workers: 1, //! duration: 0, //! summarize_last: 0, @@ -159,8 +159,8 @@ use std::env; use std::time::Duration; -use log::info; use tokio::time::sleep; +use tracing::info; use crate::{app, bootstrap}; diff --git a/src/core/auth.rs b/src/core/auth.rs index b5326a37..94d455d7 100644 --- a/src/core/auth.rs +++ b/src/core/auth.rs @@ -42,7 +42,6 @@ use std::sync::Arc; use std::time::Duration; use derive_more::Display; -use log::debug; use rand::distributions::Alphanumeric; use rand::{thread_rng, Rng}; use serde::{Deserialize, Serialize}; @@ -51,6 +50,7 @@ use torrust_tracker_clock::clock::Time; use torrust_tracker_clock::conv::convert_from_timestamp_to_datetime_utc; use torrust_tracker_located_error::{DynError, LocatedError}; use torrust_tracker_primitives::DurationSinceUnixEpoch; +use tracing::debug; use crate::shared::bit_torrent::common::AUTH_KEY_LENGTH; use crate::CurrentClock; diff --git a/src/core/databases/mysql.rs b/src/core/databases/mysql.rs index ca95fa0b..ebb002d3 100644 --- a/src/core/databases/mysql.rs +++ b/src/core/databases/mysql.rs @@ -3,13 +3,13 @@ use std::str::FromStr; use std::time::Duration; use async_trait::async_trait; -use log::debug; use r2d2::Pool; use r2d2_mysql::mysql::prelude::Queryable; use r2d2_mysql::mysql::{params, Opts, OptsBuilder}; use r2d2_mysql::MySqlConnectionManager; use torrust_tracker_primitives::info_hash::InfoHash; use torrust_tracker_primitives::{DatabaseDriver, PersistentTorrents}; +use tracing::debug; use super::{Database, Error}; use crate::core::auth::{self, Key}; diff --git a/src/core/mod.rs b/src/core/mod.rs index 6628426c..c05eb402 100644 --- a/src/core/mod.rs +++ b/src/core/mod.rs @@ -312,7 +312,7 @@ //! You can control the behavior of this module with the module settings: //! //! ```toml -//! log_level = "debug" +//! trace_level = "debug" //! mode = "public" //! db_driver = "Sqlite3" //! db_path = "./storage/tracker/lib/database/sqlite3.db" @@ -442,7 +442,6 @@ use std::sync::Arc; use std::time::Duration; use derive_more::Constructor; -use log::debug; use tokio::sync::mpsc::error::SendError; use torrust_tracker_clock::clock::Time; use torrust_tracker_configuration::{AnnouncePolicy, Configuration, TrackerPolicy, TORRENT_PEERS_LIMIT}; @@ -452,6 +451,7 @@ use torrust_tracker_primitives::torrent_metrics::TorrentsMetrics; use torrust_tracker_primitives::{peer, TrackerMode}; use torrust_tracker_torrent_repository::entry::EntrySync; use torrust_tracker_torrent_repository::repository::Repository; +use tracing::debug; use self::auth::Key; use self::error::Error; diff --git a/src/core/statistics.rs b/src/core/statistics.rs index f38662cd..d7192f5d 100644 --- a/src/core/statistics.rs +++ b/src/core/statistics.rs @@ -20,11 +20,11 @@ use std::sync::Arc; use async_trait::async_trait; -use log::debug; #[cfg(test)] use mockall::{automock, predicate::str}; use tokio::sync::mpsc::error::SendError; use tokio::sync::{mpsc, RwLock, RwLockReadGuard}; +use tracing::debug; const CHANNEL_BUFFER_SIZE: usize = 65_535; diff --git a/src/lib.rs b/src/lib.rs index 064f50eb..8e052499 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -153,7 +153,7 @@ //! db_path = "./storage/tracker/lib/database/sqlite3.db" //! external_ip = "0.0.0.0" //! inactive_peer_cleanup_interval = 600 -//! log_level = "info" +//! trace_level = "info" //! max_peer_timeout = 900 //! min_announce_interval = 120 //! mode = "public" diff --git a/src/main.rs b/src/main.rs index bd07f4a5..bad1fdb1 100644 --- a/src/main.rs +++ b/src/main.rs @@ -1,5 +1,5 @@ -use log::info; use torrust_tracker::{app, bootstrap}; +use tracing::info; #[tokio::main] async fn main() { diff --git a/src/servers/apis/mod.rs b/src/servers/apis/mod.rs index 2d4b3abe..17a9126d 100644 --- a/src/servers/apis/mod.rs +++ b/src/servers/apis/mod.rs @@ -42,7 +42,7 @@ //! //! ```text //! Loading configuration from config file ./tracker.toml -//! 023-03-28T12:19:24.963054069+01:00 [torrust_tracker::bootstrap::logging][INFO] logging initialized. +//! 023-03-28T12:19:24.963054069+01:00 [torrust_tracker::bootstrap::tracing][INFO] tracing initialized. //! ... //! 023-03-28T12:19:24.964138723+01:00 [torrust_tracker::bootstrap::jobs::tracker_apis][INFO] Starting Torrust APIs server on: http://0.0.0.0:1212 //! ``` diff --git a/src/servers/apis/server.rs b/src/servers/apis/server.rs index e7289055..26e9409b 100644 --- a/src/servers/apis/server.rs +++ b/src/servers/apis/server.rs @@ -30,9 +30,9 @@ use axum_server::tls_rustls::RustlsConfig; use axum_server::Handle; use derive_more::Constructor; use futures::future::BoxFuture; -use log::{debug, error, info}; use tokio::sync::oneshot::{Receiver, Sender}; use torrust_tracker_configuration::AccessTokens; +use tracing::{debug, error, info}; use super::routes::router; use crate::bootstrap::jobs::Started; diff --git a/src/servers/apis/v1/context/torrent/handlers.rs b/src/servers/apis/v1/context/torrent/handlers.rs index 15f70c8b..b2418c68 100644 --- a/src/servers/apis/v1/context/torrent/handlers.rs +++ b/src/servers/apis/v1/context/torrent/handlers.rs @@ -7,11 +7,11 @@ use std::sync::Arc; use axum::extract::{Path, State}; use axum::response::{IntoResponse, Response}; use axum_extra::extract::Query; -use log::debug; use serde::{de, Deserialize, Deserializer}; use thiserror::Error; use torrust_tracker_primitives::info_hash::InfoHash; use torrust_tracker_primitives::pagination::Pagination; +use tracing::debug; use super::responses::{torrent_info_response, torrent_list_response, torrent_not_known_response}; use crate::core::services::torrent::{get_torrent_info, get_torrents, get_torrents_page}; diff --git a/src/servers/health_check_api/server.rs b/src/servers/health_check_api/server.rs index 05ed605f..f0375357 100644 --- a/src/servers/health_check_api/server.rs +++ b/src/servers/health_check_api/server.rs @@ -12,14 +12,13 @@ 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::{MakeRequestUuid, SetRequestIdLayer}; use tower_http::trace::{DefaultMakeSpan, TraceLayer}; -use tracing::{Level, Span}; +use tracing::{debug, Level, Span}; use crate::bootstrap::jobs::Started; use crate::servers::health_check_api::handlers::health_check_handler; diff --git a/src/servers/http/server.rs b/src/servers/http/server.rs index decc734c..4f64e64f 100644 --- a/src/servers/http/server.rs +++ b/src/servers/http/server.rs @@ -6,8 +6,8 @@ use axum_server::tls_rustls::RustlsConfig; use axum_server::Handle; use derive_more::Constructor; use futures::future::BoxFuture; -use log::info; use tokio::sync::oneshot::{Receiver, Sender}; +use tracing::info; use super::v1::routes::router; use crate::bootstrap::jobs::Started; diff --git a/src/servers/http/v1/handlers/announce.rs b/src/servers/http/v1/handlers/announce.rs index e9198f20..0b009f70 100644 --- a/src/servers/http/v1/handlers/announce.rs +++ b/src/servers/http/v1/handlers/announce.rs @@ -11,10 +11,10 @@ use std::sync::Arc; use axum::extract::State; use axum::response::{IntoResponse, Response}; -use log::debug; use torrust_tracker_clock::clock::Time; use torrust_tracker_primitives::announce_event::AnnounceEvent; use torrust_tracker_primitives::{peer, NumberOfBytes}; +use tracing::debug; use crate::core::auth::Key; use crate::core::{AnnounceData, Tracker}; diff --git a/src/servers/http/v1/handlers/scrape.rs b/src/servers/http/v1/handlers/scrape.rs index d6b39cc5..17260763 100644 --- a/src/servers/http/v1/handlers/scrape.rs +++ b/src/servers/http/v1/handlers/scrape.rs @@ -9,7 +9,7 @@ use std::sync::Arc; use axum::extract::State; use axum::response::{IntoResponse, Response}; -use log::debug; +use tracing::debug; use crate::core::auth::Key; use crate::core::{ScrapeData, Tracker}; diff --git a/src/servers/registar.rs b/src/servers/registar.rs index 9c23573c..6058595b 100644 --- a/src/servers/registar.rs +++ b/src/servers/registar.rs @@ -5,9 +5,9 @@ use std::net::SocketAddr; use std::sync::Arc; use derive_more::Constructor; -use log::debug; use tokio::sync::Mutex; use tokio::task::JoinHandle; +use tracing::debug; /// A [`ServiceHeathCheckResult`] is returned by a completed health check. pub type ServiceHeathCheckResult = Result; diff --git a/src/servers/signals.rs b/src/servers/signals.rs index 42fd868e..0a1a0631 100644 --- a/src/servers/signals.rs +++ b/src/servers/signals.rs @@ -2,8 +2,8 @@ use std::time::Duration; use derive_more::Display; -use log::info; use tokio::time::sleep; +use tracing::info; /// This is the message that the "launcher" spawned task receives from the main /// application process to notify the service to shutdown. diff --git a/src/servers/udp/handlers.rs b/src/servers/udp/handlers.rs index 2d5038ec..891c206c 100644 --- a/src/servers/udp/handlers.rs +++ b/src/servers/udp/handlers.rs @@ -9,19 +9,19 @@ use aquatic_udp_protocol::{ AnnounceInterval, AnnounceRequest, AnnounceResponse, ConnectRequest, ConnectResponse, ErrorResponse, NumberOfDownloads, NumberOfPeers, Port, Request, Response, ResponsePeer, ScrapeRequest, ScrapeResponse, TorrentScrapeStatistics, TransactionId, }; -use log::debug; use tokio::net::UdpSocket; use torrust_tracker_located_error::DynError; use torrust_tracker_primitives::info_hash::InfoHash; +use tracing::debug; use uuid::Uuid; use super::connection_cookie::{check, from_connection_id, into_connection_id, make}; use super::UdpRequest; use crate::core::{statistics, ScrapeData, Tracker}; use crate::servers::udp::error::Error; -use crate::servers::udp::logging::{log_bad_request, log_error_response, log_request, log_response}; use crate::servers::udp::peer_builder; use crate::servers::udp::request::AnnounceWrapper; +use crate::servers::udp::tracing::{trace_bad_request, trace_error_response, trace_request, trace_response}; use crate::shared::bit_torrent::common::MAX_SCRAPE_TORRENTS; /// It handles the incoming UDP packets. @@ -48,7 +48,7 @@ pub(crate) async fn handle_packet(udp_request: UdpRequest, tracker: &Arc { - log_request(&request, &request_id, &server_socket_addr); + trace_request(&request, &request_id, &server_socket_addr); let transaction_id = match &request { Request::Connect(connect_request) => connect_request.transaction_id, @@ -63,12 +63,12 @@ pub(crate) async fn handle_packet(udp_request: UdpRequest, tracker: &Arc { - log_bad_request(&request_id); + trace_bad_request(&request_id); let response = handle_error( &Error::BadRequest { @@ -77,7 +77,7 @@ pub(crate) async fn handle_packet(udp_request: UdpRequest, tracker: &Arc { }, }; - trace!("Running UDP Tracker on Socket: {}", running_udp_server.state.binding); + info!("Running UDP Tracker on Socket: {}", running_udp_server.state.binding); Ok(running_udp_server) } diff --git a/src/servers/udp/logging.rs b/src/servers/udp/tracing.rs similarity index 91% rename from src/servers/udp/logging.rs rename to src/servers/udp/tracing.rs index 9bbb48f6..04617731 100644 --- a/src/servers/udp/logging.rs +++ b/src/servers/udp/tracing.rs @@ -1,4 +1,4 @@ -//! Logging for UDP Tracker requests and responses. +//! Tracing for UDP Tracker requests and responses. use std::net::SocketAddr; use std::time::Duration; @@ -8,7 +8,7 @@ use torrust_tracker_primitives::info_hash::InfoHash; use super::handlers::RequestId; -pub fn log_request(request: &Request, request_id: &RequestId, server_socket_addr: &SocketAddr) { +pub fn trace_request(request: &Request, request_id: &RequestId, server_socket_addr: &SocketAddr) { let action = map_action_name(request); match &request { @@ -56,7 +56,7 @@ fn map_action_name(udp_request: &Request) -> String { } } -pub fn log_response( +pub fn trace_response( _response: &Response, transaction_id: &TransactionId, request_id: &RequestId, @@ -73,13 +73,13 @@ pub fn log_response( latency_ms = %latency.as_millis()); } -pub fn log_bad_request(request_id: &RequestId) { +pub fn trace_bad_request(request_id: &RequestId) { tracing::span!( target: "UDP TRACKER", tracing::Level::INFO, "bad request", request_id = %request_id); } -pub fn log_error_response(request_id: &RequestId) { +pub fn trace_error_response(request_id: &RequestId) { tracing::span!( target: "UDP TRACKER", tracing::Level::INFO, "response", request_id = %request_id); diff --git a/src/shared/bit_torrent/tracker/udp/client.rs b/src/shared/bit_torrent/tracker/udp/client.rs index 11c8d8f6..58a3ed8b 100644 --- a/src/shared/bit_torrent/tracker/udp/client.rs +++ b/src/shared/bit_torrent/tracker/udp/client.rs @@ -4,9 +4,9 @@ use std::sync::Arc; use std::time::Duration; use aquatic_udp_protocol::{ConnectRequest, Request, Response, TransactionId}; -use log::debug; use tokio::net::UdpSocket; use tokio::time; +use tracing::debug; use crate::shared::bit_torrent::tracker::udp::{source_address, MAX_PACKET_SIZE}; diff --git a/tests/servers/health_check_api/environment.rs b/tests/servers/health_check_api/environment.rs index 0856985d..818f085d 100644 --- a/tests/servers/health_check_api/environment.rs +++ b/tests/servers/health_check_api/environment.rs @@ -1,7 +1,6 @@ use std::net::SocketAddr; use std::sync::Arc; -use log::debug; use tokio::sync::oneshot::{self, Sender}; use tokio::task::JoinHandle; use torrust_tracker::bootstrap::jobs::Started; @@ -9,6 +8,7 @@ use torrust_tracker::servers::health_check_api::server; use torrust_tracker::servers::registar::Registar; use torrust_tracker::servers::signals::{self, Halted}; use torrust_tracker_configuration::HealthCheckApi; +use tracing::debug; #[derive(Debug)] pub enum Error {