From 2472936857a7a8f7852b060cdaf96ac6c65c7f83 Mon Sep 17 00:00:00 2001 From: h7x4 Date: Sun, 30 Nov 2025 20:42:10 +0900 Subject: [PATCH] Switch from `log` to `tracing` --- Cargo.lock | 161 +++++++++--------- Cargo.toml | 8 +- src/core/bootstrap.rs | 47 +++-- src/core/common.rs | 2 +- src/server/command.rs | 38 +++-- src/server/config.rs | 6 +- src/server/session_handler.rs | 20 +-- src/server/sql/database_operations.rs | 10 +- .../sql/database_privilege_operations.rs | 12 +- src/server/sql/user_operations.rs | 20 +-- src/server/supervisor.rs | 85 +++++---- 11 files changed, 217 insertions(+), 192 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 673b481..10c5766 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -220,6 +220,7 @@ checksum = "9d92b1fab272fe943881b77cc6e920d6543e5b1bfadbd5ed81c7c5a755742394" dependencies = [ "clap", "log", + "tracing-core", ] [[package]] @@ -506,29 +507,6 @@ dependencies = [ "syn", ] -[[package]] -name = "env_filter" -version = "0.1.4" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "1bf3c259d255ca70051b30e2e95b5446cdb8949ac4cd22c0d7fd634d89f568e2" -dependencies = [ - "log", - "regex", -] - -[[package]] -name = "env_logger" -version = "0.11.8" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "13c863f0904021b108aa8b2f55046443e6b1ebde8fd4a15c399893aae4fa069f" -dependencies = [ - "anstream", - "anstyle", - "env_filter", - "jiff", - "log", -] - [[package]] name = "equivalent" version = "1.0.2" @@ -946,30 +924,6 @@ version = "1.0.15" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "4a5f13b858c8d314ee3e8f639011f7ccefe71f97f96e50151fb991f267928e2c" -[[package]] -name = "jiff" -version = "0.2.16" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "49cce2b81f2098e7e3efc35bc2e0a6b7abec9d34128283d7a26fa8f32a6dbb35" -dependencies = [ - "jiff-static", - "log", - "portable-atomic", - "portable-atomic-util", - "serde_core", -] - -[[package]] -name = "jiff-static" -version = "0.2.16" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "980af8b43c3ad5d8d349ace167ec8170839f753a42d233ba19e08afe1850fa69" -dependencies = [ - "proc-macro2", - "quote", - "syn", -] - [[package]] name = "js-sys" version = "0.3.82" @@ -1097,11 +1051,9 @@ dependencies = [ "clap_complete", "derive_more", "dialoguer", - "env_logger", "futures-util", "indoc", "itertools", - "log", "nix", "num_cpus", "prettytable", @@ -1111,12 +1063,14 @@ dependencies = [ "serde", "serde_json", "sqlx", - "systemd-journal-logger", "tokio", "tokio-serde", "tokio-stream", "tokio-util", "toml", + "tracing", + "tracing-journald", + "tracing-subscriber", "uuid", ] @@ -1133,6 +1087,15 @@ dependencies = [ "memoffset", ] +[[package]] +name = "nu-ansi-term" +version = "0.50.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "7957b9740744892f114936ab4a57b3f487491bbeafaf8083688b16841a4240e5" +dependencies = [ + "windows-sys 0.60.2", +] + [[package]] name = "num-bigint-dig" version = "0.8.6" @@ -1304,21 +1267,6 @@ version = "0.3.32" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "7edddbd0b52d732b21ad9a5fab5c704c14cd949e5e9a1ec5929a24fded1b904c" -[[package]] -name = "portable-atomic" -version = "1.11.1" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "f84267b20a16ea918e43c6a88433c2d54fa145c92a811b5b047ccbe153674483" - -[[package]] -name = "portable-atomic-util" -version = "0.2.4" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "d8a2f0d8d040d7848a709caf78912debcc3f33ee4b3cac47d73d1e1069e83507" -dependencies = [ - "portable-atomic", -] - [[package]] name = "potential_utf" version = "0.1.4" @@ -1678,6 +1626,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 = "shell-words" version = "1.1.0" @@ -1994,16 +1951,6 @@ dependencies = [ "syn", ] -[[package]] -name = "systemd-journal-logger" -version = "2.2.2" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "7266304d24ca5a4b230545fc558c80e18bd3e1d2eb1be149b6bcd04398d3e79c" -dependencies = [ - "log", - "rustix", -] - [[package]] name = "tempfile" version = "3.23.0" @@ -2068,6 +2015,15 @@ dependencies = [ "syn", ] +[[package]] +name = "thread_local" +version = "1.1.9" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f60246a4944f24f6e018aa17cdeffb7818b76356965d03b07d6a9886e8962185" +dependencies = [ + "cfg-if", +] + [[package]] name = "tinystr" version = "0.8.2" @@ -2201,9 +2157,9 @@ checksum = "df8b2b54733674ad286d16267dcfc7a71ed5c776e4ac7aa3c3e2561f7c637bf2" [[package]] name = "tracing" -version = "0.1.41" +version = "0.1.43" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "784e0ac535deb450455cbfa28a6f0df145ea1bb7ae51b821cf5e7927fdcfbdd0" +checksum = "2d15d90a0b5c19378952d479dc858407149d7bb45a14de0142f6c534b16fc647" dependencies = [ "log", "pin-project-lite", @@ -2213,9 +2169,9 @@ dependencies = [ [[package]] name = "tracing-attributes" -version = "0.1.30" +version = "0.1.31" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "81383ab64e72a7a8b8e13130c49e3dab29def6d0c7d76a03087b3cf71c5c6903" +checksum = "7490cfa5ec963746568740651ac6781f701c9c5ea257c58e057f3ba8cf69e8da" dependencies = [ "proc-macro2", "quote", @@ -2224,11 +2180,48 @@ dependencies = [ [[package]] name = "tracing-core" -version = "0.1.34" +version = "0.1.35" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "b9d12581f227e93f094d3af2ae690a574abb8a2b9b7a96e7cfe9647b2b617678" +checksum = "7a04e24fab5c89c6a36eb8558c9656f30d81de51dfa4d3b45f26b21d61fa0a6c" dependencies = [ "once_cell", + "valuable", +] + +[[package]] +name = "tracing-journald" +version = "0.3.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "2d3a81ed245bfb62592b1e2bc153e77656d94ee6a0497683a65a12ccaf2438d0" +dependencies = [ + "libc", + "tracing-core", + "tracing-subscriber", +] + +[[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-subscriber" +version = "0.3.22" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "2f30143827ddab0d256fd843b7a66d164e9f271cfa0dde49142c5ca0ca291f1e" +dependencies = [ + "nu-ansi-term", + "sharded-slab", + "smallvec", + "thread_local", + "tracing-core", + "tracing-log", ] [[package]] @@ -2329,6 +2322,12 @@ dependencies = [ "wasm-bindgen", ] +[[package]] +name = "valuable" +version = "0.1.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ba73ea9cf16a25df0c8caa16c51acb937d5712a8429db78a3ee29d5dcacd3a65" + [[package]] name = "vcpkg" version = "0.2.15" diff --git a/Cargo.toml b/Cargo.toml index 0e9b4d7..9df0482 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -21,15 +21,13 @@ anyhow = "1.0.100" async-bincode = "0.8.0" bincode = "2.0.1" clap = { version = "4.5.53", features = ["derive"] } -clap-verbosity-flag = "3.0.4" +clap-verbosity-flag = { version = "3.0.4", features = [ "tracing" ] } clap_complete = "4.5.61" derive_more = { version = "2.0.1", features = ["display", "error"] } dialoguer = "0.12.0" -env_logger = "0.11.8" futures-util = "0.3.31" indoc = "2.0.7" itertools = "0.14.0" -log = "0.4.28" nix = { version = "0.30.1", features = ["fs", "process", "socket", "user"] } num_cpus = "1.17.0" prettytable = "0.10.0" @@ -38,12 +36,14 @@ sd-notify = "0.4.5" serde = "1.0.228" serde_json = { version = "1.0.145", features = ["preserve_order"] } sqlx = { version = "0.8.6", features = ["runtime-tokio", "mysql", "tls-rustls"] } -systemd-journal-logger = "2.2.2" tokio = { version = "1.48.0", features = ["rt-multi-thread", "macros", "signal"] } tokio-serde = { version = "0.9.0", features = ["bincode"] } tokio-stream = "0.1.17" tokio-util = { version = "0.7.17", features = ["codec", "rt"] } toml = "0.9.8" +tracing = { version = "0.1.43", features = ["log"] } +tracing-journald = "0.3.2" +tracing-subscriber = "0.3.22" uuid = { version = "1.18.1", features = ["v4"] } [features] diff --git a/src/core/bootstrap.rs b/src/core/bootstrap.rs index cf9c8a2..d591835 100644 --- a/src/core/bootstrap.rs +++ b/src/core/bootstrap.rs @@ -6,6 +6,7 @@ use nix::libc::{EXIT_SUCCESS, exit}; use sqlx::mysql::MySqlPoolOptions; use std::os::unix::net::UnixStream as StdUnixStream; use tokio::{net::UnixStream as TokioUnixStream, sync::RwLock}; +use tracing_subscriber::prelude::*; use crate::{ core::common::{ @@ -83,9 +84,18 @@ pub fn bootstrap_server_connection_and_drop_privileges( "The executable should not be SUID or SGID when connecting to an external server" ); - env_logger::Builder::new() - .filter_level(verbose.log_level_filter()) - .init(); + let subscriber = tracing_subscriber::Registry::default() + .with(verbose.tracing_level_filter()) + .with( + tracing_subscriber::fmt::layer() + .with_line_number(cfg!(debug_assertions)) + .with_target(cfg!(debug_assertions)) + .with_thread_ids(false) + .with_thread_names(false), + ); + + tracing::subscriber::set_global_default(subscriber) + .context("Failed to set global default tracing subscriber")?; connect_to_external_server(server_socket_path) } else if cfg!(feature = "suid-sgid-mode") { @@ -93,9 +103,18 @@ pub fn bootstrap_server_connection_and_drop_privileges( // as we might be running with elevated privileges. let server_connection = bootstrap_internal_server_and_drop_privs(config)?; - env_logger::Builder::new() - .filter_level(verbose.log_level_filter()) - .init(); + let subscriber = tracing_subscriber::Registry::default() + .with(verbose.tracing_level_filter()) + .with( + tracing_subscriber::fmt::layer() + .with_line_number(cfg!(debug_assertions)) + .with_target(cfg!(debug_assertions)) + .with_thread_ids(false) + .with_thread_names(false), + ); + + tracing::subscriber::set_global_default(subscriber) + .context("Failed to set global default tracing subscriber")?; Ok(server_connection) } else { @@ -108,7 +127,7 @@ fn connect_to_external_server( ) -> anyhow::Result { // TODO: ensure this is both readable and writable if let Some(socket_path) = server_socket_path { - log::debug!("Connecting to socket at {:?}", socket_path); + tracing::debug!("Connecting to socket at {:?}", socket_path); return match StdUnixStream::connect(socket_path) { Ok(socket) => Ok(socket), Err(e) => match e.kind() { @@ -120,7 +139,7 @@ fn connect_to_external_server( } if fs::metadata(DEFAULT_SOCKET_PATH).is_ok() { - log::debug!("Connecting to default socket at {:?}", DEFAULT_SOCKET_PATH); + tracing::debug!("Connecting to default socket at {:?}", DEFAULT_SOCKET_PATH); return match StdUnixStream::connect(DEFAULT_SOCKET_PATH) { Ok(socket) => Ok(socket), Err(e) => match e.kind() { @@ -140,7 +159,7 @@ fn connect_to_external_server( /// If the process is not running with elevated privileges, this function /// is a no-op. fn drop_privs() -> anyhow::Result<()> { - log::debug!("Dropping privileges"); + tracing::debug!("Dropping privileges"); let real_uid = nix::unistd::getuid(); let real_gid = nix::unistd::getgid(); @@ -150,7 +169,7 @@ fn drop_privs() -> anyhow::Result<()> { debug_assert_eq!(nix::unistd::getuid(), real_uid); debug_assert_eq!(nix::unistd::getgid(), real_gid); - log::debug!("Privileges dropped successfully"); + tracing::debug!("Privileges dropped successfully"); Ok(()) } @@ -167,7 +186,7 @@ fn bootstrap_internal_server_and_drop_privs( return Err(anyhow::anyhow!("Config file not found or not readable")); } - log::debug!("Starting server with config at {:?}", config_path); + tracing::debug!("Starting server with config at {:?}", config_path); let socket = invoke_server_with_config(config_path)?; drop_privs()?; return Ok(socket); @@ -178,7 +197,7 @@ fn bootstrap_internal_server_and_drop_privs( if !executable_is_suid_or_sgid()? { anyhow::bail!("Executable is not SUID/SGID - refusing to start internal sever"); } - log::debug!("Starting server with default config at {:?}", config_path); + tracing::debug!("Starting server with default config at {:?}", config_path); let socket = invoke_server_with_config(config_path)?; drop_privs()?; return Ok(socket); @@ -198,11 +217,11 @@ fn invoke_server_with_config(config_path: PathBuf) -> anyhow::Result { - log::debug!("Forked child process with PID {}", child); + tracing::debug!("Forked child process with PID {}", child); Ok(client_socket) } nix::unistd::ForkResult::Child => { - log::debug!("Running server in child process"); + tracing::debug!("Running server in child process"); match run_forked_server(config_path, server_socket, unix_user) { Err(e) => Err(e), diff --git a/src/core/common.rs b/src/core/common.rs index 90f99f9..af406b1 100644 --- a/src/core/common.rs +++ b/src/core/common.rs @@ -31,7 +31,7 @@ fn get_unix_groups(user: &LibcUser) -> anyhow::Result> { Ok(Some(group)) => Some(group), Ok(None) => None, Err(e) => { - log::warn!( + tracing::warn!( "Failed to look up group with GID {}: {}\nIgnoring...", gid, e diff --git a/src/server/command.rs b/src/server/command.rs index ea37c45..b62267c 100644 --- a/src/server/command.rs +++ b/src/server/command.rs @@ -3,7 +3,7 @@ use std::path::PathBuf; use anyhow::Context; use clap::Parser; use clap_verbosity_flag::Verbosity; -use systemd_journal_logger::JournalLog; +use tracing_subscriber::prelude::*; use crate::{core::common::DEFAULT_CONFIG_PATH, server::supervisor::Supervisor}; @@ -50,29 +50,39 @@ pub async fn handle_command( false } }; + if systemd_mode { - JournalLog::new() - .context("Failed to initialize journald logging")? - .install() - .context("Failed to install journald logger")?; + let subscriber = tracing_subscriber::Registry::default() + .with(verbosity.tracing_level_filter()) + .with(tracing_journald::layer()?); - log::set_max_level(verbosity.log_level_filter()); + tracing::subscriber::set_global_default(subscriber) + .context("Failed to set global default tracing subscriber")?; - if verbosity.log_level_filter() >= log::LevelFilter::Trace { - log::warn!("{}", LOG_LEVEL_WARNING.trim()); + if verbosity.tracing_level_filter() >= tracing::Level::TRACE { + tracing::warn!("{}", LOG_LEVEL_WARNING.trim()); } if auto_detected_systemd_mode { - log::info!("Running in systemd mode, auto-detected"); + tracing::info!("Running in systemd mode, auto-detected"); } else { - log::info!("Running in systemd mode"); + tracing::info!("Running in systemd mode"); } } else { - env_logger::Builder::new() - .filter_level(verbosity.log_level_filter()) - .init(); + let subscriber = tracing_subscriber::Registry::default() + .with(verbosity.tracing_level_filter()) + .with( + tracing_subscriber::fmt::layer() + .with_line_number(cfg!(debug_assertions)) + .with_target(cfg!(debug_assertions)) + .with_thread_ids(false) + .with_thread_names(false), + ); - log::info!("Running in standalone mode"); + tracing::subscriber::set_global_default(subscriber) + .context("Failed to set global default tracing subscriber")?; + + tracing::info!("Running in standalone mode"); } let config_path = config_path.unwrap_or_else(|| PathBuf::from(DEFAULT_CONFIG_PATH)); diff --git a/src/server/config.rs b/src/server/config.rs index 73f44c8..fdfdf90 100644 --- a/src/server/config.rs +++ b/src/server/config.rs @@ -35,7 +35,7 @@ impl MysqlConfig { pub fn as_mysql_connect_options(&self) -> anyhow::Result { let mut options = MySqlConnectOptions::new() .database("mysql") - .log_statements(log::LevelFilter::Trace); + .log_statements(tracing::log::LevelFilter::Trace); if let Some(username) = &self.username { options = options.username(username); @@ -63,7 +63,7 @@ impl MysqlConfig { .password .as_ref() .map(|_| "".to_owned()); - log::debug!( + tracing::debug!( "Connecting to MySQL server with parameters: {:#?}", display_config ); @@ -79,7 +79,7 @@ pub struct ServerConfig { impl ServerConfig { /// Reads the server configuration from the specified path, or the default path if none is provided. pub fn read_config_from_path(config_path: &Path) -> anyhow::Result { - log::debug!("Reading config file at {:?}", config_path); + tracing::debug!("Reading config file at {:?}", config_path); fs::read_to_string(config_path) .context(format!("Failed to read config file at {:?}", config_path)) diff --git a/src/server/session_handler.rs b/src/server/session_handler.rs index 43edd8b..3ba0341 100644 --- a/src/server/session_handler.rs +++ b/src/server/session_handler.rs @@ -40,7 +40,7 @@ pub async fn session_handler( let uid = match socket.peer_cred() { Ok(cred) => cred.uid(), Err(e) => { - log::error!("Failed to get peer credentials from socket: {}", e); + tracing::error!("Failed to get peer credentials from socket: {}", e); let mut message_stream = create_server_to_client_message_stream(socket); message_stream .send(Response::Error( @@ -56,12 +56,12 @@ pub async fn session_handler( } }; - log::debug!("Validated peer UID: {}", uid); + tracing::debug!("Validated peer UID: {}", uid); let unix_user = match UnixUser::from_uid(uid) { Ok(user) => user, Err(e) => { - log::error!("Failed to get username from uid: {}", e); + tracing::error!("Failed to get username from uid: {}", e); let mut message_stream = create_server_to_client_message_stream(socket); message_stream .send(Response::Error( @@ -87,7 +87,7 @@ pub async fn session_handler_with_unix_user( ) -> anyhow::Result<()> { let mut message_stream = create_server_to_client_message_stream(socket); - log::debug!("Requesting database connection from pool"); + tracing::debug!("Requesting database connection from pool"); let mut db_connection = match db_pool.read().await.acquire().await { Ok(connection) => connection, Err(err) => { @@ -104,12 +104,12 @@ pub async fn session_handler_with_unix_user( return Err(err.into()); } }; - log::debug!("Successfully acquired database connection from pool"); + tracing::debug!("Successfully acquired database connection from pool"); let result = session_handler_with_db_connection(message_stream, unix_user, &mut db_connection).await; - log::debug!("Releasing database connection back to pool"); + tracing::debug!("Releasing database connection back to pool"); result } @@ -131,7 +131,7 @@ async fn session_handler_with_db_connection( Some(Ok(request)) => request, Some(Err(e)) => return Err(e.into()), None => { - log::warn!("Client disconnected without sending an exit message"); + tracing::warn!("Client disconnected without sending an exit message"); break; } }; @@ -143,7 +143,7 @@ async fn session_handler_with_db_connection( } request => request.to_owned(), }; - log::info!("Received request: {:#?}", request_to_display); + tracing::info!("Received request: {:#?}", request_to_display); let response = match request { Request::CheckAuthorization(dbs_or_users) => { @@ -237,11 +237,11 @@ async fn session_handler_with_db_connection( } response => response.to_owned(), }; - log::info!("Response: {:#?}", response_to_display); + tracing::info!("Response: {:#?}", response_to_display); stream.send(response).await?; stream.flush().await?; - log::debug!("Successfully processed request"); + tracing::debug!("Successfully processed request"); } Ok(()) diff --git a/src/server/sql/database_operations.rs b/src/server/sql/database_operations.rs index e1ca273..cb8f53b 100644 --- a/src/server/sql/database_operations.rs +++ b/src/server/sql/database_operations.rs @@ -33,7 +33,7 @@ pub(super) async fn unsafe_database_exists( .await; if let Err(err) = &result { - log::error!( + tracing::error!( "Failed to check if database '{}' exists: {:?}", &database_name, err @@ -93,7 +93,7 @@ pub async fn create_databases( .map_err(|err| CreateDatabaseError::MySqlError(err.to_string())); if let Err(err) = &result { - log::error!("Failed to create database '{}': {:?}", &database_name, err); + tracing::error!("Failed to create database '{}': {:?}", &database_name, err); } results.insert(database_name, result); @@ -152,7 +152,7 @@ pub async fn drop_databases( .map_err(|err| DropDatabaseError::MySqlError(err.to_string())); if let Err(err) = &result { - log::error!("Failed to drop database '{}': {:?}", &database_name, err); + tracing::error!("Failed to drop database '{}': {:?}", &database_name, err); } results.insert(database_name, result); @@ -216,7 +216,7 @@ pub async fn list_databases( }); if let Err(err) = &result { - log::error!("Failed to list database '{}': {:?}", &database_name, err); + tracing::error!("Failed to list database '{}': {:?}", &database_name, err); } results.insert(database_name, result); @@ -243,7 +243,7 @@ pub async fn list_all_databases_for_user( .map_err(|err| ListAllDatabasesError::MySqlError(err.to_string())); if let Err(err) = &result { - log::error!( + tracing::error!( "Failed to list databases for user '{}': {:?}", unix_user.username, err diff --git a/src/server/sql/database_privilege_operations.rs b/src/server/sql/database_privilege_operations.rs index fcdb3d3..80d5ac3 100644 --- a/src/server/sql/database_privilege_operations.rs +++ b/src/server/sql/database_privilege_operations.rs @@ -50,7 +50,7 @@ fn get_mysql_row_priv_field(row: &MySqlRow, position: usize) -> Result Ok(val), _ => { - log::warn!(r#"Invalid value for privilege "{}": '{}'"#, field, value); + tracing::warn!(r#"Invalid value for privilege "{}": '{}'"#, field, value); Ok(false) } } @@ -94,7 +94,7 @@ async fn unsafe_get_database_privileges( .await; if let Err(e) = &result { - log::error!( + tracing::error!( "Failed to get database privileges for '{}': {}", &database_name, e @@ -124,7 +124,7 @@ pub async fn unsafe_get_database_privileges_for_db_user_pair( .await; if let Err(e) = &result { - log::error!( + tracing::error!( "Failed to get database privileges for '{}.{}': {}", &database_name, &user_name, @@ -206,7 +206,7 @@ pub async fn get_all_database_privileges( .map_err(|e| GetAllDatabasesPrivilegeDataError::MySqlError(e.to_string())); if let Err(e) = &result { - log::error!("Failed to get all database privileges: {:?}", e); + tracing::error!("Failed to get all database privileges: {:?}", e); } result @@ -298,7 +298,7 @@ async fn unsafe_apply_privilege_diff( }; if let Err(e) = &result { - log::error!("Failed to apply database privilege diff: {}", e); + tracing::error!("Failed to apply database privilege diff: {}", e); } result @@ -380,7 +380,7 @@ async fn validate_diff( } } DatabasePrivilegesDiff::Noop { .. } => { - log::warn!( + tracing::warn!( "Server got sent a noop database privilege diff to validate, is the client buggy?" ); Ok(()) diff --git a/src/server/sql/user_operations.rs b/src/server/sql/user_operations.rs index 67a517c..13628bb 100644 --- a/src/server/sql/user_operations.rs +++ b/src/server/sql/user_operations.rs @@ -45,7 +45,7 @@ async fn unsafe_user_exists( .map(|row| row.get::(0)); if let Err(err) = &result { - log::error!("Failed to check if database user exists: {:?}", err); + tracing::error!("Failed to check if database user exists: {:?}", err); } result @@ -88,7 +88,7 @@ pub async fn create_database_users( .map_err(|err| CreateUserError::MySqlError(err.to_string())); if let Err(err) = &result { - log::error!("Failed to create database user '{}': {:?}", &db_user, err); + tracing::error!("Failed to create database user '{}': {:?}", &db_user, err); } results.insert(db_user, result); @@ -134,7 +134,7 @@ pub async fn drop_database_users( .map_err(|err| DropUserError::MySqlError(err.to_string())); if let Err(err) = &result { - log::error!("Failed to drop database user '{}': {:?}", &db_user, err); + tracing::error!("Failed to drop database user '{}': {:?}", &db_user, err); } results.insert(db_user, result); @@ -177,7 +177,7 @@ pub async fn set_password_for_database_user( .map_err(|err| SetPasswordError::MySqlError(err.to_string())); if result.is_err() { - log::error!( + tracing::error!( "Failed to set password for database user '{}': ", &db_user, ); @@ -208,7 +208,7 @@ async fn database_user_is_locked_unsafe( .map(|row| row.get::(0)); if let Err(err) = &result { - log::error!( + tracing::error!( "Failed to check if database user is locked '{}': {:?}", &db_user, err @@ -269,7 +269,7 @@ pub async fn lock_database_users( .map_err(|err| LockUserError::MySqlError(err.to_string())); if let Err(err) = &result { - log::error!("Failed to lock database user '{}': {:?}", &db_user, err); + tracing::error!("Failed to lock database user '{}': {:?}", &db_user, err); } results.insert(db_user, result); @@ -329,7 +329,7 @@ pub async fn unlock_database_users( .map_err(|err| UnlockUserError::MySqlError(err.to_string())); if let Err(err) = &result { - log::error!("Failed to unlock database user '{}': {:?}", &db_user, err); + tracing::error!("Failed to unlock database user '{}': {:?}", &db_user, err); } results.insert(db_user, result); @@ -403,7 +403,7 @@ pub async fn list_database_users( .await; if let Err(err) = &result { - log::error!("Failed to list database user '{}': {:?}", &db_user, err); + tracing::error!("Failed to list database user '{}': {:?}", &db_user, err); } if let Ok(Some(user)) = result.as_mut() { @@ -433,7 +433,7 @@ pub async fn list_all_database_users_for_unix_user( .map_err(|err| ListAllUsersError::MySqlError(err.to_string())); if let Err(err) = &result { - log::error!("Failed to list all database users: {:?}", err); + tracing::error!("Failed to list all database users: {:?}", err); } if let Ok(users) = result.as_mut() { @@ -468,7 +468,7 @@ pub async fn append_databases_where_user_has_privileges( .await; if let Err(err) = &database_list { - log::error!( + tracing::error!( "Failed to list databases for user '{}': {:?}", &db_user.user, err diff --git a/src/server/supervisor.rs b/src/server/supervisor.rs index 9701078..97d8760 100644 --- a/src/server/supervisor.rs +++ b/src/server/supervisor.rs @@ -56,8 +56,8 @@ pub struct Supervisor { impl Supervisor { pub async fn new(config_path: PathBuf, systemd_mode: bool) -> anyhow::Result { - log::debug!("Starting server supervisor"); - log::debug!( + tracing::debug!("Starting server supervisor"); + tracing::debug!( "Running in tokio with {} worker threads", tokio::runtime::Handle::current().metrics().num_workers() ); @@ -70,13 +70,13 @@ impl Supervisor { let watchdog_task = if systemd_mode && sd_notify::watchdog_enabled(true, &mut watchdog_micro_seconds) { watchdog_duration = Some(Duration::from_micros(watchdog_micro_seconds)); - log::debug!( + tracing::debug!( "Systemd watchdog enabled with {} millisecond interval", watchdog_micro_seconds.div_ceil(1000), ); Some(spawn_watchdog_task(watchdog_duration.unwrap())) } else { - log::debug!("Systemd watchdog not enabled, skipping watchdog thread"); + tracing::debug!("Systemd watchdog not enabled, skipping watchdog thread"); None }; @@ -133,7 +133,7 @@ impl Supervisor { }) } - async fn stop_receiving_new_connections(&self) -> anyhow::Result<()> { + fn stop_receiving_new_connections(&self) -> anyhow::Result<()> { self.handler_task_tracker.close(); self.supervisor_message_sender .send(SupervisorMessage::StopAcceptingNewConnections) @@ -141,7 +141,7 @@ impl Supervisor { Ok(()) } - async fn resume_receiving_new_connections(&self) -> anyhow::Result<()> { + fn resume_receiving_new_connections(&self) -> anyhow::Result<()> { self.handler_task_tracker.reopen(); self.supervisor_message_sender .send(SupervisorMessage::ResumeAcceptingNewConnections) @@ -194,30 +194,30 @@ impl Supervisor { // NOTE: despite closing the existing db pool, any already acquired connections will remain valid until dropped, // so we don't need to close existing connections here. if self.config.lock().await.mysql != previous_config.mysql { - log::debug!("MySQL configuration has changed"); + tracing::debug!("MySQL configuration has changed"); - log::debug!("Restarting database connection pool with new configuration"); + tracing::debug!("Restarting database connection pool with new configuration"); self.restart_db_connection_pool().await?; } if self.config.lock().await.socket_path != previous_config.socket_path { - log::debug!("Socket path configuration has changed, reloading listener"); + tracing::debug!("Socket path configuration has changed, reloading listener"); if !listener_task_was_stopped { listener_task_was_stopped = true; - log::debug!("Stop accepting new connections"); - self.stop_receiving_new_connections().await?; + tracing::debug!("Stop accepting new connections"); + self.stop_receiving_new_connections()?; - log::debug!("Waiting for existing connections to finish"); + tracing::debug!("Waiting for existing connections to finish"); self.wait_for_existing_connections_to_finish().await?; } - log::debug!("Reloading listener with new socket path"); + tracing::debug!("Reloading listener with new socket path"); self.reload_listener().await?; } if listener_task_was_stopped { - log::debug!("Resuming listener task"); - self.resume_receiving_new_connections().await?; + tracing::debug!("Resuming listener task"); + self.resume_receiving_new_connections()?; } sd_notify::notify(false, &[sd_notify::NotifyState::Ready])?; @@ -228,31 +228,28 @@ impl Supervisor { pub async fn shutdown(&self) -> anyhow::Result<()> { sd_notify::notify(false, &[sd_notify::NotifyState::Stopping])?; - log::debug!("Stop accepting new connections"); - self.stop_receiving_new_connections().await?; + tracing::debug!("Stop accepting new connections"); + self.stop_receiving_new_connections()?; let connection_count = self.handler_task_tracker.len(); - log::debug!( + tracing::debug!( "Waiting for {} existing connections to finish", connection_count ); self.wait_for_existing_connections_to_finish().await?; - log::debug!("Shutting down listener task"); + tracing::debug!("Shutting down listener task"); self.supervisor_message_sender .send(SupervisorMessage::Shutdown) .unwrap_or_else(|e| { - log::warn!( - "Failed to send shutdown message to listener task: {}", - e - ); + tracing::warn!("Failed to send shutdown message to listener task: {}", e); 0 }); - log::debug!("Shutting down database connection pool"); + tracing::debug!("Shutting down database connection pool"); self.db_connection_pool.read().await.close().await; - log::debug!("Server shutdown complete"); + tracing::debug!("Server shutdown complete"); std::process::exit(0); } @@ -266,19 +263,19 @@ impl Supervisor { let mut rx = self.reload_message_receiver.resubscribe(); rx.recv().await } => { - log::info!("Reloading configuration"); + tracing::info!("Reloading configuration"); match self.reload().await { Ok(()) => { - log::info!("Configuration reloaded successfully"); + tracing::info!("Configuration reloaded successfully"); } Err(e) => { - log::error!("Failed to reload configuration: {}", e); + tracing::error!("Failed to reload configuration: {}", e); } } } _ = self.shutdown_cancel_token.cancelled() => { - log::info!("Shutting down server"); + tracing::info!("Shutting down server"); self.shutdown().await?; break; } @@ -292,14 +289,14 @@ impl Supervisor { fn spawn_watchdog_task(duration: Duration) -> JoinHandle<()> { tokio::spawn(async move { let mut interval = interval(duration.div_f32(2.0)); - log::debug!( + tracing::debug!( "Starting systemd watchdog task, pinging every {} milliseconds", duration.div_f32(2.0).as_millis() ); loop { interval.tick().await; if let Err(err) = sd_notify::notify(false, &[sd_notify::NotifyState::Watchdog]) { - log::warn!("Failed to notify systemd watchdog: {}", err); + tracing::warn!("Failed to notify systemd watchdog: {}", err); } } }) @@ -323,7 +320,7 @@ fn spawn_status_notifier_task(task_tracker: TaskTracker) -> JoinHandle<()> { if let Err(e) = sd_notify::notify(false, &[sd_notify::NotifyState::Status(message.as_str())]) { - log::warn!("Failed to send systemd status notification: {}", e); + tracing::warn!("Failed to send systemd status notification: {}", e); } } }) @@ -334,11 +331,11 @@ async fn create_unix_listener_with_socket_path( ) -> anyhow::Result { let parent_directory = socket_path.parent().unwrap(); if !parent_directory.exists() { - log::debug!("Creating directory {:?}", parent_directory); + tracing::debug!("Creating directory {:?}", parent_directory); fs::create_dir_all(parent_directory)?; } - log::info!("Listening on socket {:?}", socket_path); + tracing::info!("Listening on socket {:?}", socket_path); match fs::remove_file(socket_path.as_path()) { Ok(_) => {} @@ -359,7 +356,7 @@ async fn create_unix_listener_with_systemd_socket() -> anyhow::Result anyhow::Result { - log::info!("Received SIGHUP signal"); + tracing::info!("Received SIGHUP signal"); reload_sender.send(ReloadEvent).ok(); } _ = sigterm_stream.recv() => { - log::info!("Received SIGTERM signal"); + tracing::info!("Received SIGTERM signal"); shutdown_token.cancel(); break; } @@ -442,16 +439,16 @@ async fn listener_task( Ok(message) = supervisor_message_receiver.recv() => { match message { SupervisorMessage::StopAcceptingNewConnections => { - log::info!("Listener task received stop accepting new connections message, stopping listener"); + tracing::info!("Listener task received stop accepting new connections message, stopping listener"); while let Ok(msg) = supervisor_message_receiver.try_recv() { if let SupervisorMessage::ResumeAcceptingNewConnections = msg { - log::info!("Listener task received resume accepting new connections message, resuming listener"); + tracing::info!("Listener task received resume accepting new connections message, resuming listener"); break; } } } SupervisorMessage::Shutdown => { - log::info!("Listener task received shutdown message, exiting listener task"); + tracing::info!("Listener task received shutdown message, exiting listener task"); break; } _ => {} @@ -464,20 +461,20 @@ async fn listener_task( } => { match accept_result { Ok((conn, _addr)) => { - log::debug!("Got new connection"); + tracing::debug!("Got new connection"); let db_pool_clone = db_pool.clone(); task_tracker.spawn(async { match session_handler(conn, db_pool_clone).await { Ok(()) => {} Err(e) => { - log::error!("Failed to run server: {}", e); + tracing::error!("Failed to run server: {}", e); } } }); } Err(e) => { - log::error!("Failed to accept new connection: {}", e); + tracing::error!("Failed to accept new connection: {}", e); } } }