From 3ccc0e41599dff371e4f8bc49eaa4d972b2f3627 Mon Sep 17 00:00:00 2001 From: Jose Celano Date: Mon, 10 Jun 2024 15:12:08 +0100 Subject: [PATCH 1/6] chore(deps): add cargo dependency tracing We will move from `log` to `tracing` crate. --- Cargo.lock | 82 +++++++++++++++++++++++++++++++ Cargo.toml | 1 + packages/located-error/Cargo.toml | 1 + 3 files changed, 84 insertions(+) diff --git a/Cargo.lock b/Cargo.lock index d3f5766d5..ab7512536 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -2339,6 +2339,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.5" @@ -2448,6 +2458,12 @@ dependencies = [ "vcpkg", ] +[[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" @@ -3441,6 +3457,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" @@ -3668,6 +3693,16 @@ dependencies = [ "syn 2.0.66", ] +[[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.36" @@ -3899,6 +3934,7 @@ dependencies = [ "tower-http", "trace", "tracing", + "tracing-subscriber", "url", "uuid", "zerocopy", @@ -3943,6 +3979,7 @@ version = "3.0.0-alpha.12-develop" dependencies = [ "log", "thiserror", + "tracing", ] [[package]] @@ -4074,6 +4111,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]] @@ -4162,6 +4238,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.9.0" diff --git a/Cargo.toml b/Cargo.toml index 5183c6067..6166831e2 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -80,6 +80,7 @@ tower = { version = "0.4.13", features = ["timeout"] } tower-http = { version = "0", features = ["compression-full", "cors", "propagate-header", "request-id", "trace"] } trace = "0" tracing = "0" +tracing-subscriber = { version = "0.3.18", features = ["json"] } url = "2" uuid = { version = "1", features = ["v4"] } zerocopy = "0.7.33" diff --git a/packages/located-error/Cargo.toml b/packages/located-error/Cargo.toml index fa3d1d76d..f34f9bc88 100644 --- a/packages/located-error/Cargo.toml +++ b/packages/located-error/Cargo.toml @@ -16,6 +16,7 @@ version.workspace = true [dependencies] log = { version = "0", features = ["release_max_level_info"] } +tracing = "0.1.40" [dev-dependencies] thiserror = "1" From 6e06b2e7aaeacb5307e494e28c4f45f08a96892b Mon Sep 17 00:00:00 2001 From: Jose Celano Date: Mon, 10 Jun 2024 15:30:25 +0100 Subject: [PATCH 2/6] refactor: [#884] move from log to tracing crate --- packages/located-error/src/lib.rs | 2 +- src/app.rs | 2 +- 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 | 73 ++++++++++++------- src/console/ci/e2e/docker.rs | 2 +- src/console/ci/e2e/logs_parser.rs | 34 ++++----- src/console/ci/e2e/runner.rs | 27 ++----- src/console/ci/e2e/tracker_checker.rs | 2 +- src/console/ci/e2e/tracker_container.rs | 2 +- src/console/clients/checker/app.rs | 27 ++----- src/console/clients/checker/checks/http.rs | 2 +- src/console/clients/checker/checks/udp.rs | 2 +- src/console/clients/udp/app.rs | 27 ++----- src/console/clients/udp/checker.rs | 2 +- src/console/profiling.rs | 2 +- src/core/auth.rs | 2 +- src/core/databases/mysql.rs | 2 +- src/core/mod.rs | 2 +- src/core/statistics.rs | 2 +- src/main.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 | 2 +- src/servers/udp/server.rs | 2 +- src/shared/bit_torrent/tracker/udp/client.rs | 2 +- tests/servers/health_check_api/environment.rs | 2 +- 37 files changed, 112 insertions(+), 141 deletions(-) diff --git a/packages/located-error/src/lib.rs b/packages/located-error/src/lib.rs index 49e135600..bfd4d4a86 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/src/app.rs b/src/app.rs index fcb01a696..b41f4098e 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/jobs/health_check_api.rs b/src/bootstrap/jobs/health_check_api.rs index fdedaa3e9..c22a4cf95 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 9ae8995fc..e9eb6bc16 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 e20d243c6..316e5746c 100644 --- a/src/bootstrap/jobs/mod.rs +++ b/src/bootstrap/jobs/mod.rs @@ -89,10 +89,10 @@ use std::panic::Location; use std::sync::Arc; use axum_server::tls_rustls::RustlsConfig; -use log::info; use thiserror::Error; use torrust_tracker_configuration::TslConfig; 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 bd3b2e332..992e7e644 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::v1::core::Core; +use tracing::info; use crate::core; diff --git a/src/bootstrap/jobs/tracker_apis.rs b/src/bootstrap/jobs/tracker_apis.rs index 834574edb..3c1f13255 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 853cb7461..2c09e6de2 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 index 5c7e93811..914ede0c4 100644 --- a/src/bootstrap/logging.rs +++ b/src/bootstrap/logging.rs @@ -12,55 +12,72 @@ //! Refer to the [configuration crate documentation](https://docs.rs/torrust-tracker-configuration) to know how to change log settings. use std::sync::Once; -use log::{info, LevelFilter}; use torrust_tracker_configuration::{Configuration, LogLevel}; +use tracing::info; +use tracing::level_filters::LevelFilter; 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.core.log_level); + let tracing_level = config_level_or_default(&cfg.core.log_level); - if level == log::LevelFilter::Off { + if tracing_level == LevelFilter::OFF { return; } INIT.call_once(|| { - stdout_config(level); + tracing_stdout_init(tracing_level, &TraceStyle::Default); }); } fn config_level_or_default(log_level: &Option) -> LevelFilter { match log_level { - None => log::LevelFilter::Info, + None => LevelFilter::INFO, Some(level) => match level { - LogLevel::Off => LevelFilter::Off, - LogLevel::Error => LevelFilter::Error, - LogLevel::Warn => LevelFilter::Warn, - LogLevel::Info => LevelFilter::Info, - LogLevel::Debug => LevelFilter::Debug, - LogLevel::Trace => LevelFilter::Trace, + LogLevel::Off => LevelFilter::OFF, + LogLevel::Error => LevelFilter::ERROR, + LogLevel::Warn => LevelFilter::WARN, + LogLevel::Info => LevelFilter::INFO, + LogLevel::Debug => LevelFilter::DEBUG, + LogLevel::Trace => LevelFilter::TRACE, }, } } -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.") - } +fn tracing_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(), + }; info!("logging initialized."); } + +#[derive(Debug)] +pub enum TraceStyle { + Default, + Pretty(bool), + 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) + } +} diff --git a/src/console/ci/e2e/docker.rs b/src/console/ci/e2e/docker.rs index c024efbae..26b7f7708 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 {} diff --git a/src/console/ci/e2e/logs_parser.rs b/src/console/ci/e2e/logs_parser.rs index 6d3349196..2d215a569 100644 --- 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 = "[UDP TRACKER][INFO] Starting on: udp://"; -const HTTP_TRACKER_PATTERN: &str = "[HTTP TRACKER][INFO] Starting on: "; -const HEALTH_CHECK_PATTERN: &str = "[HEALTH CHECK API][INFO] Starting on: "; +const 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: "; #[derive(Serialize, Deserialize, Debug, Default)] pub struct RunningServices { @@ -18,17 +18,17 @@ impl RunningServices { /// 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 + /// 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 /// ``` /// /// It would extract these services: @@ -86,9 +86,9 @@ mod tests { #[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"; + 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); assert_eq!(running_services.udp_trackers, vec!["127.0.0.1:8080"]); diff --git a/src/console/ci/e2e/runner.rs b/src/console/ci/e2e/runner.rs index 945a87033..c44ce464e 100644 --- a/src/console/ci/e2e/runner.rs +++ b/src/console/ci/e2e/runner.rs @@ -3,7 +3,8 @@ //! ```text //! cargo run --bin e2e_tests_runner share/default/config/tracker.e2e.container.sqlite3.toml //! ``` -use log::{debug, info, LevelFilter}; +use tracing::info; +use tracing::level_filters::LevelFilter; use super::tracker_container::TrackerContainer; use crate::console::ci::e2e::docker::RunOptions; @@ -32,7 +33,7 @@ pub struct Arguments { /// /// Will panic if it can't not perform any of the operations. pub fn run() { - setup_runner_logging(LevelFilter::Info); + tracing_stdout_init(LevelFilter::INFO); let args = parse_arguments(); @@ -76,25 +77,9 @@ 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.") - } - - debug!("logging initialized."); +fn tracing_stdout_init(filter: LevelFilter) { + tracing_subscriber::fmt().with_max_level(filter).init(); + info!("logging initialized."); } fn parse_arguments() -> Arguments { diff --git a/src/console/ci/e2e/tracker_checker.rs b/src/console/ci/e2e/tracker_checker.rs index edc679802..b2fd7df2e 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 5a4d11d02..0cb4fec7c 100644 --- a/src/console/ci/e2e/tracker_container.rs +++ b/src/console/ci/e2e/tracker_container.rs @@ -1,8 +1,8 @@ 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; diff --git a/src/console/clients/checker/app.rs b/src/console/clients/checker/app.rs index 82ea800d0..84802688d 100644 --- a/src/console/clients/checker/app.rs +++ b/src/console/clients/checker/app.rs @@ -17,7 +17,8 @@ use std::sync::Arc; use anyhow::{Context, Result}; use clap::Parser; -use log::{debug, LevelFilter}; +use tracing::info; +use tracing::level_filters::LevelFilter; use super::config::Configuration; use super::console::Console; @@ -40,7 +41,7 @@ struct Args { /// /// Will return an error if the configuration was not provided. pub async fn run() -> Result> { - setup_logging(LevelFilter::Info); + tracing_stdout_init(LevelFilter::INFO); let args = Args::parse(); @@ -56,25 +57,9 @@ 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.") - } - - debug!("logging initialized."); +fn tracing_stdout_init(filter: LevelFilter) { + tracing_subscriber::fmt().with_max_level(filter).init(); + info!("logging 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 e526b5e57..57f8c3015 100644 --- a/src/console/clients/checker/checks/http.rs +++ b/src/console/clients/checker/checks/http.rs @@ -1,8 +1,8 @@ use std::str::FromStr; -use log::debug; use reqwest::Url as ServiceUrl; use torrust_tracker_primitives::info_hash::InfoHash; +use tracing::debug; use url::Url; use super::structs::{CheckerOutput, Status}; diff --git a/src/console/clients/checker/checks/udp.rs b/src/console/clients/checker/checks/udp.rs index 6458190d4..072aa5ca7 100644 --- a/src/console/clients/checker/checks/udp.rs +++ b/src/console/clients/checker/checks/udp.rs @@ -2,8 +2,8 @@ use std::net::SocketAddr; use aquatic_udp_protocol::{Port, TransactionId}; use hex_literal::hex; -use log::debug; use torrust_tracker_primitives::info_hash::InfoHash; +use tracing::debug; use crate::console::clients::checker::checks::structs::{CheckerOutput, Status}; use crate::console::clients::checker::service::{CheckError, CheckResult}; diff --git a/src/console/clients/udp/app.rs b/src/console/clients/udp/app.rs index d2c986cd9..c780157f4 100644 --- a/src/console/clients/udp/app.rs +++ b/src/console/clients/udp/app.rs @@ -62,8 +62,9 @@ use std::str::FromStr; use anyhow::Context; use aquatic_udp_protocol::{Port, Response, TransactionId}; use clap::{Parser, Subcommand}; -use log::{debug, LevelFilter}; use torrust_tracker_primitives::info_hash::InfoHash as TorrustInfoHash; +use tracing::level_filters::LevelFilter; +use tracing::{debug, info}; use url::Url; use crate::console::clients::udp::checker; @@ -102,7 +103,7 @@ enum Command { /// /// pub async fn run() -> anyhow::Result<()> { - setup_logging(LevelFilter::Info); + tracing_stdout_init(LevelFilter::INFO); let args = Args::parse(); @@ -125,25 +126,9 @@ pub async fn run() -> anyhow::Result<()> { Ok(()) } -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.") - } - - debug!("logging initialized."); +fn tracing_stdout_init(filter: LevelFilter) { + tracing_subscriber::fmt().with_max_level(filter).init(); + info!("logging 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 37928f0df..afde63d12 100644 --- a/src/console/clients/udp/checker.rs +++ b/src/console/clients/udp/checker.rs @@ -6,9 +6,9 @@ use aquatic_udp_protocol::{ AnnounceActionPlaceholder, 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 d77e55966..c95354d6f 100644 --- a/src/console/profiling.rs +++ b/src/console/profiling.rs @@ -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 b5326a373..94d455d7e 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 ca95fa0b9..ebb002d31 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 e81ad2a94..6af28199f 100644 --- a/src/core/mod.rs +++ b/src/core/mod.rs @@ -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::v1::core::Core; @@ -453,6 +452,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 f38662cdd..d7192f5d1 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/main.rs b/src/main.rs index bd07f4a58..bad1fdb1e 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/server.rs b/src/servers/apis/server.rs index 57d2629ae..7c5b8983b 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 15f70c8b6..b2418c689 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 05ed605f4..f03753573 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 33e20a84e..5c33fc8fa 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 e9198f20c..0b009f700 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 d6b39cc53..172607637 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 9c23573c4..6058595ba 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 42fd868e8..0a1a06312 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 4064cf041..858d6606c 100644 --- a/src/servers/udp/handlers.rs +++ b/src/servers/udp/handlers.rs @@ -10,10 +10,10 @@ use aquatic_udp_protocol::{ ErrorResponse, Ipv4AddrBytes, Ipv6AddrBytes, 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 zerocopy::network_endian::I32; diff --git a/src/servers/udp/server.rs b/src/servers/udp/server.rs index be4c36d40..dd30d9d6d 100644 --- a/src/servers/udp/server.rs +++ b/src/servers/udp/server.rs @@ -22,13 +22,13 @@ use std::sync::Arc; use aquatic_udp_protocol::Response; use derive_more::Constructor; -use log::{debug, error, info, trace}; use ringbuf::traits::{Consumer, Observer, Producer}; use ringbuf::StaticRb; use tokio::net::UdpSocket; use tokio::sync::oneshot; use tokio::task::{AbortHandle, JoinHandle}; use tokio::{select, task}; +use tracing::{debug, error, info, trace}; use super::UdpRequest; use crate::bootstrap::jobs::Started; diff --git a/src/shared/bit_torrent/tracker/udp/client.rs b/src/shared/bit_torrent/tracker/udp/client.rs index 81209efb6..45b51ad35 100644 --- a/src/shared/bit_torrent/tracker/udp/client.rs +++ b/src/shared/bit_torrent/tracker/udp/client.rs @@ -6,9 +6,9 @@ use std::time::Duration; use anyhow::{anyhow, Context, Result}; use aquatic_udp_protocol::{ConnectRequest, Request, Response, TransactionId}; -use log::debug; use tokio::net::UdpSocket; use tokio::time; +use tracing::debug; use zerocopy::network_endian::I32; 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 c200beaeb..a50ad5156 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 { From 69f100ab7d38cde396546ea3b1a34f7c718bd62d Mon Sep 17 00:00:00 2001 From: Jose Celano Date: Mon, 10 Jun 2024 17:01:40 +0100 Subject: [PATCH 3/6] refactor: [#884] move from log to tracing crate --- packages/configuration/src/lib.rs | 2 +- .../config/tracker.e2e.container.sqlite3.toml | 4 + src/bootstrap/logging.rs | 2 +- src/console/ci/e2e/docker.rs | 2 + src/console/ci/e2e/logs_parser.rs | 73 +++++++++++++------ src/console/ci/e2e/runner.rs | 7 +- src/console/ci/e2e/tracker_container.rs | 4 +- src/console/clients/checker/app.rs | 2 +- src/console/clients/udp/app.rs | 2 +- src/servers/udp/server.rs | 2 +- 10 files changed, 70 insertions(+), 30 deletions(-) diff --git a/packages/configuration/src/lib.rs b/packages/configuration/src/lib.rs index 62792c271..46ece96ab 100644 --- 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 index e7d8fa279..767b56116 100644 --- 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 index 914ede0c4..5194f06ea 100644 --- a/src/bootstrap/logging.rs +++ b/src/bootstrap/logging.rs @@ -46,7 +46,7 @@ fn config_level_or_default(log_level: &Option) -> 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 index 26b7f7708..32a0c3e56 100644 --- 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 index 2d215a569..a9277524e 100644 --- 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 = 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 index c44ce464e..aeb28b777 100644 --- 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 index 0cb4fec7c..dc7036faa 100644 --- 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 index 84802688d..ade1d4820 100644 --- a/src/console/clients/checker/app.rs +++ b/src/console/clients/checker/app.rs @@ -58,7 +58,7 @@ pub async fn run() -> 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/console/clients/udp/app.rs b/src/console/clients/udp/app.rs index c780157f4..323fca1b6 100644 --- 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 index dd30d9d6d..b2c72258d 100644 --- 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(); From 7de259524724bc0036e075b4ee4df1d9fefd53c9 Mon Sep 17 00:00:00 2001 From: Jose Celano Date: Mon, 10 Jun 2024 17:04:15 +0100 Subject: [PATCH 4/6] chore(deps): [#884] remove unused crate log We have moved to tracing crate. --- Cargo.lock | 2 -- Cargo.toml | 1 - packages/located-error/Cargo.toml | 1 - 3 files changed, 4 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index ab7512536..c71ee890d 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -3904,7 +3904,6 @@ dependencies = [ "hyper-util", "lazy_static", "local-ip-address", - "log", "mockall", "multimap", "parking_lot", @@ -3977,7 +3976,6 @@ dependencies = [ name = "torrust-tracker-located-error" version = "3.0.0-alpha.12-develop" dependencies = [ - "log", "thiserror", "tracing", ] diff --git a/Cargo.toml b/Cargo.toml index 6166831e2..94ad9a02c 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -52,7 +52,6 @@ http-body = "1.0.0" hyper = "1" hyper-util = { version = "0.1.3", features = ["http1", "http2", "tokio"] } lazy_static = "1" -log = { version = "0", features = ["release_max_level_info"] } multimap = "0" parking_lot = "0.12.1" percent-encoding = "2" diff --git a/packages/located-error/Cargo.toml b/packages/located-error/Cargo.toml index f34f9bc88..4b2c73178 100644 --- a/packages/located-error/Cargo.toml +++ b/packages/located-error/Cargo.toml @@ -15,7 +15,6 @@ rust-version.workspace = true version.workspace = true [dependencies] -log = { version = "0", features = ["release_max_level_info"] } tracing = "0.1.40" [dev-dependencies] From d6fd11a0b736a4e20abfdea02cb84c79c64f7168 Mon Sep 17 00:00:00 2001 From: Jose Celano Date: Mon, 10 Jun 2024 17:23:55 +0100 Subject: [PATCH 5/6] test: [#884] add test for parsing array of services from app logs The tracker can run multiple UDP or HTTP trackers. We parse the services from app output but there was not test for multiple services of the same type (UDP or HTTP tracker). --- src/console/ci/e2e/logs_parser.rs | 72 +++++++++++++++++++------------ 1 file changed, 45 insertions(+), 27 deletions(-) diff --git a/src/console/ci/e2e/logs_parser.rs b/src/console/ci/e2e/logs_parser.rs index a9277524e..2a1876a11 100644 --- a/src/console/ci/e2e/logs_parser.rs +++ b/src/console/ci/e2e/logs_parser.rs @@ -19,17 +19,19 @@ impl RunningServices { /// /// ```text /// Loading configuration from default configuration file: `./share/default/config/tracker.development.sqlite3.toml` ... - /// 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 + /// 2024-06-10T16:07:39.989540Z INFO torrust_tracker::bootstrap::logging: logging initialized. + /// 2024-06-10T16:07:39.990205Z INFO UDP TRACKER: Starting on: udp://0.0.0.0:6868 + /// 2024-06-10T16:07:39.990215Z INFO UDP TRACKER: Started on: udp://0.0.0.0:6868 + /// 2024-06-10T16:07:39.990244Z INFO UDP TRACKER: Starting on: udp://0.0.0.0:6969 + /// 2024-06-10T16:07:39.990255Z INFO UDP TRACKER: Started on: udp://0.0.0.0:6969 + /// 2024-06-10T16:07:39.990261Z INFO torrust_tracker::bootstrap::jobs: TLS not enabled + /// 2024-06-10T16:07:39.990303Z INFO HTTP TRACKER: Starting on: http://0.0.0.0:7070 + /// 2024-06-10T16:07:39.990439Z INFO HTTP TRACKER: Started on: http://0.0.0.0:7070 + /// 2024-06-10T16:07:39.990448Z INFO torrust_tracker::bootstrap::jobs: TLS not enabled + /// 2024-06-10T16:07:39.990563Z INFO API: Starting on http://127.0.0.1:1212 + /// 2024-06-10T16:07:39.990565Z INFO API: Started on http://127.0.0.1:1212 + /// 2024-06-10T16:07:39.990577Z INFO HEALTH CHECK API: Starting on: http://127.0.0.1:1313 + /// 2024-06-10T16:07:39.990638Z INFO HEALTH CHECK API: Started on: http://127.0.0.1:1313 /// ``` /// /// It would extract these services: @@ -48,7 +50,7 @@ impl RunningServices { /// } /// ``` /// - /// NOTICE: Using colors in the console output could affect this method + /// 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 { @@ -89,7 +91,7 @@ mod tests { #[test] fn it_should_parse_from_logs_with_valid_logs() { - let log = r#" + let logs = r#" Loading configuration from environment variable db_path = "/var/lib/torrust/tracker/database/sqlite3.db" [[udp_trackers]] @@ -103,22 +105,22 @@ mod tests { [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 + + Loading configuration from default configuration file: `./share/default/config/tracker.development.sqlite3.toml` ... + 2024-06-10T16:07:39.989540Z INFO torrust_tracker::bootstrap::logging: logging initialized. + 2024-06-10T16:07:39.990244Z INFO UDP TRACKER: Starting on: udp://0.0.0.0:6969 + 2024-06-10T16:07:39.990255Z INFO UDP TRACKER: Started on: udp://0.0.0.0:6969 + 2024-06-10T16:07:39.990261Z INFO torrust_tracker::bootstrap::jobs: TLS not enabled + 2024-06-10T16:07:39.990303Z INFO HTTP TRACKER: Starting on: http://0.0.0.0:7070 + 2024-06-10T16:07:39.990439Z INFO HTTP TRACKER: Started on: http://0.0.0.0:7070 + 2024-06-10T16:07:39.990448Z INFO torrust_tracker::bootstrap::jobs: TLS not enabled + 2024-06-10T16:07:39.990563Z INFO API: Starting on http://127.0.0.1:1212 + 2024-06-10T16:07:39.990565Z INFO API: Started on http://127.0.0.1:1212 + 2024-06-10T16:07:39.990577Z INFO HEALTH CHECK API: Starting on: http://127.0.0.1:1313 + 2024-06-10T16:07:39.990638Z INFO HEALTH CHECK API: Started on: http://127.0.0.1:1313 "#; - let running_services = RunningServices::parse_from_logs(log); + let running_services = RunningServices::parse_from_logs(logs); 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"]); @@ -128,6 +130,7 @@ mod tests { #[test] fn it_should_ignore_logs_with_no_matching_lines() { 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()); @@ -135,6 +138,21 @@ mod tests { assert!(running_services.health_checks.is_empty()); } + #[test] + fn it_should_parse_multiple_services() { + let logs = " + 2024-06-10T16:07:39.990205Z INFO UDP TRACKER: Starting on: udp://0.0.0.0:6868 + 2024-06-10T16:07:39.990215Z INFO UDP TRACKER: Started on: udp://0.0.0.0:6868 + + 2024-06-10T16:07:39.990244Z INFO UDP TRACKER: Starting on: udp://0.0.0.0:6969 + 2024-06-10T16:07:39.990255Z INFO UDP TRACKER: Started on: udp://0.0.0.0:6969 + "; + + let running_services = RunningServices::parse_from_logs(logs); + + assert_eq!(running_services.udp_trackers, vec!["127.0.0.1:6868", "127.0.0.1:6969"]); + } + #[test] fn it_should_replace_wildcard_ip_with_localhost() { let address = "0.0.0.0:8080"; From ec88dbfffdeac08bbc3aa69de90ffad9e2711023 Mon Sep 17 00:00:00 2001 From: Jose Celano Date: Mon, 10 Jun 2024 17:24:25 +0100 Subject: [PATCH 6/6] chore(deps): remove unused dependencies log and fern We have moved from crate log to tracing. --- Cargo.lock | 10 ---------- Cargo.toml | 1 - 2 files changed, 11 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index c71ee890d..36508e261 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1259,15 +1259,6 @@ version = "2.1.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "9fc0510504f03c51ada170672ac806f1f105a88aa97a5281117e1ddc3368e51a" -[[package]] -name = "fern" -version = "0.6.2" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "d9f0c14694cbd524c8720dd69b0e3179344f04ebb5f90f2e4a440c6ea3b2f1ee" -dependencies = [ - "log", -] - [[package]] name = "figment" version = "0.10.19" @@ -3894,7 +3885,6 @@ dependencies = [ "crossbeam-skiplist", "dashmap", "derive_more", - "fern", "figment", "futures", "futures-util", diff --git a/Cargo.toml b/Cargo.toml index 94ad9a02c..418bcb3ed 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -43,7 +43,6 @@ clap = { version = "4", features = ["derive", "env"] } crossbeam-skiplist = "0.1" dashmap = "5.5.3" derive_more = "0" -fern = "0" figment = "0.10.18" futures = "0" futures-util = "0.3.30"