From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from firstgate.proxmox.com (firstgate.proxmox.com [IPv6:2a01:7e0:0:424::9]) by lore.proxmox.com (Postfix) with ESMTPS id 447C11FF2A7 for ; Mon, 1 Jul 2024 11:27:07 +0200 (CEST) Received: from firstgate.proxmox.com (localhost [127.0.0.1]) by firstgate.proxmox.com (Proxmox) with ESMTP id 03E6931E1C; Mon, 1 Jul 2024 11:27:21 +0200 (CEST) From: Gabriel Goller To: pbs-devel@lists.proxmox.com Date: Mon, 1 Jul 2024 11:26:31 +0200 Message-ID: <20240701092642.106030-3-g.goller@proxmox.com> X-Mailer: git-send-email 2.43.0 In-Reply-To: <20240701092642.106030-1-g.goller@proxmox.com> References: <20240701092642.106030-1-g.goller@proxmox.com> MIME-Version: 1.0 X-SPAM-LEVEL: Spam detection results: 0 AWL -0.057 Adjusted score from AWL reputation of From: address BAYES_00 -1.9 Bayes spam probability is 0 to 1% DMARC_MISSING 0.1 Missing DMARC policy KAM_DMARC_STATUS 0.01 Test Rule for DKIM or SPF Failure with Strict Alignment SPF_HELO_NONE 0.001 SPF: HELO does not publish an SPF Record SPF_PASS -0.001 SPF: sender matches SPF record Subject: [pbs-devel] [PATCH proxmox v7 2/4] enable tracing logger, remove task_log macros X-BeenThere: pbs-devel@lists.proxmox.com X-Mailman-Version: 2.1.29 Precedence: list List-Id: Proxmox Backup Server development discussion List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Reply-To: Proxmox Backup Server development discussion Cc: Lukas Wagner Content-Type: text/plain; charset="us-ascii" Content-Transfer-Encoding: 7bit Errors-To: pbs-devel-bounces@lists.proxmox.com Sender: "pbs-devel" Enable the tracing-system by setting the LOGGER task local variable to a instance of a FileLogger and initializing the WARN_COUNTER. Removed the task_log! macros and some occurences. Reviewed-by: Lukas Wagner Tested-by: Lukas Wagner Signed-off-by: Gabriel Goller --- proxmox-rest-server/Cargo.toml | 4 +- proxmox-rest-server/src/api_config.rs | 3 +- proxmox-rest-server/src/file_logger.rs | 147 ------------------------- proxmox-rest-server/src/lib.rs | 3 - proxmox-rest-server/src/rest.rs | 4 +- proxmox-rest-server/src/worker_task.rs | 93 +++++++--------- proxmox-sys/src/worker_task_context.rs | 47 -------- 7 files changed, 46 insertions(+), 255 deletions(-) delete mode 100644 proxmox-rest-server/src/file_logger.rs diff --git a/proxmox-rest-server/Cargo.toml b/proxmox-rest-server/Cargo.toml index 20f43a69a4d0..5f92bebcec58 100644 --- a/proxmox-rest-server/Cargo.toml +++ b/proxmox-rest-server/Cargo.toml @@ -32,20 +32,20 @@ serde_json.workspace = true tokio = { workspace = true, features = ["signal", "process"] } tokio-openssl.workspace = true tokio-stream.workspace = true +tracing.workspace = true tower-service.workspace = true url.workspace = true -tracing.workspace = true proxmox-async.workspace = true proxmox-compression.workspace = true proxmox-http = { workspace = true, optional = true } proxmox-io.workspace = true proxmox-lang.workspace = true +proxmox-log.workspace = true proxmox-router.workspace = true proxmox-schema = { workspace = true, features = [ "api-macro", "upid-api-impl" ] } proxmox-sys = { workspace = true, features = [ "logrotate", "timer" ] } proxmox-time.workspace = true -proxmox-log.workspace = true [features] default = [] diff --git a/proxmox-rest-server/src/api_config.rs b/proxmox-rest-server/src/api_config.rs index eaece05adce2..5b7a2a4f7287 100644 --- a/proxmox-rest-server/src/api_config.rs +++ b/proxmox-rest-server/src/api_config.rs @@ -12,11 +12,12 @@ use hyper::http::request::Parts; use hyper::{Body, Response}; use tower_service::Service; +use proxmox_log::{FileLogOptions, FileLogger}; use proxmox_router::{Router, RpcEnvironmentType, UserInformation}; use proxmox_sys::fs::{create_path, CreateOptions}; use crate::rest::Handler; -use crate::{CommandSocket, FileLogOptions, FileLogger, RestEnvironment}; +use crate::{CommandSocket, RestEnvironment}; /// REST server configuration pub struct ApiConfig { diff --git a/proxmox-rest-server/src/file_logger.rs b/proxmox-rest-server/src/file_logger.rs deleted file mode 100644 index 2bb1fac69be2..000000000000 --- a/proxmox-rest-server/src/file_logger.rs +++ /dev/null @@ -1,147 +0,0 @@ -use std::io::Write; - -use anyhow::Error; -use nix::fcntl::OFlag; - -use proxmox_sys::fs::{atomic_open_or_create_file, CreateOptions}; - -/// Options to control the behavior of a [FileLogger] instance -#[derive(Default)] -pub struct FileLogOptions { - /// Open underlying log file in append mode, useful when multiple concurrent processes - /// want to log to the same file (e.g., HTTP access log). Note that it is only atomic - /// for writes smaller than the PIPE_BUF (4k on Linux). - /// Inside the same process you may need to still use an mutex, for shared access. - pub append: bool, - /// Open underlying log file as readable - pub read: bool, - /// If set, ensure that the file is newly created or error out if already existing. - pub exclusive: bool, - /// Duplicate logged messages to STDOUT, like tee - pub to_stdout: bool, - /// Prefix messages logged to the file with the current local time as RFC 3339 - pub prefix_time: bool, - /// File owner/group and mode - pub file_opts: CreateOptions, -} - -/// Log messages with optional automatically added timestamps into files -/// -/// #### Example: -/// ``` -/// # use anyhow::{bail, format_err, Error}; -/// use proxmox_rest_server::{flog, FileLogger, FileLogOptions}; -/// -/// # std::fs::remove_file("test.log"); -/// let options = FileLogOptions { -/// to_stdout: true, -/// exclusive: true, -/// ..Default::default() -/// }; -/// let mut log = FileLogger::new("test.log", options).unwrap(); -/// flog!(log, "A simple log: {}", "Hello!"); -/// # std::fs::remove_file("test.log"); -/// ``` -pub struct FileLogger { - file: std::fs::File, - file_name: std::path::PathBuf, - options: FileLogOptions, -} - -/// Log messages to [FileLogger] - ``println`` like macro -#[macro_export] -macro_rules! flog { - ($log:expr, $($arg:tt)*) => ({ - $log.log(format!($($arg)*)); - }) -} - -impl FileLogger { - pub fn new>( - file_name: P, - options: FileLogOptions, - ) -> Result { - let file = Self::open(&file_name, &options)?; - - let file_name: std::path::PathBuf = file_name.as_ref().to_path_buf(); - - Ok(Self { - file, - file_name, - options, - }) - } - - pub fn reopen(&mut self) -> Result<&Self, Error> { - let file = Self::open(&self.file_name, &self.options)?; - self.file = file; - Ok(self) - } - - fn open>( - file_name: P, - options: &FileLogOptions, - ) -> Result { - let mut flags = OFlag::O_CLOEXEC; - - if options.read { - flags |= OFlag::O_RDWR; - } else { - flags |= OFlag::O_WRONLY; - } - - if options.append { - flags |= OFlag::O_APPEND; - } - if options.exclusive { - flags |= OFlag::O_EXCL; - } - - let file = - atomic_open_or_create_file(&file_name, flags, &[], options.file_opts.clone(), false)?; - - Ok(file) - } - - pub fn log>(&mut self, msg: S) { - let msg = msg.as_ref(); - - if self.options.to_stdout { - let mut stdout = std::io::stdout(); - stdout.write_all(msg.as_bytes()).unwrap(); - stdout.write_all(b"\n").unwrap(); - } - - let line = if self.options.prefix_time { - let now = proxmox_time::epoch_i64(); - let rfc3339 = match proxmox_time::epoch_to_rfc3339(now) { - Ok(rfc3339) => rfc3339, - Err(_) => "1970-01-01T00:00:00Z".into(), // for safety, should really not happen! - }; - format!("{}: {}\n", rfc3339, msg) - } else { - format!("{}\n", msg) - }; - if let Err(err) = self.file.write_all(line.as_bytes()) { - // avoid panicking, log methods should not do that - // FIXME: or, return result??? - log::error!("error writing to log file - {}", err); - } - } -} - -impl std::io::Write for FileLogger { - fn write(&mut self, buf: &[u8]) -> Result { - if self.options.to_stdout { - let _ = std::io::stdout().write(buf); - } - self.file.write(buf) - } - - fn flush(&mut self) -> Result<(), std::io::Error> { - if self.options.to_stdout { - let _ = std::io::stdout().flush(); - } - self.file.flush() - } -} diff --git a/proxmox-rest-server/src/lib.rs b/proxmox-rest-server/src/lib.rs index ce9e4f15e4ea..e88663662e3c 100644 --- a/proxmox-rest-server/src/lib.rs +++ b/proxmox-rest-server/src/lib.rs @@ -41,9 +41,6 @@ pub use state::*; mod command_socket; pub use command_socket::*; -mod file_logger; -pub use file_logger::{FileLogOptions, FileLogger}; - mod api_config; pub use api_config::{ApiConfig, AuthError, AuthHandler, IndexHandler, UnixAcceptor}; diff --git a/proxmox-rest-server/src/rest.rs b/proxmox-rest-server/src/rest.rs index 39ae9a185cb2..3a3c287ce3a8 100644 --- a/proxmox-rest-server/src/rest.rs +++ b/proxmox-rest-server/src/rest.rs @@ -31,10 +31,10 @@ use proxmox_schema::{ObjectSchemaType, ParameterSchema}; use proxmox_async::stream::AsyncReaderStream; use proxmox_compression::{DeflateEncoder, Level}; +use proxmox_log::FileLogger; use crate::{ - formatter::*, normalize_path, ApiConfig, AuthError, CompressionMethod, FileLogger, - RestEnvironment, + formatter::*, normalize_path, ApiConfig, AuthError, CompressionMethod, RestEnvironment, }; extern "C" { diff --git a/proxmox-rest-server/src/worker_task.rs b/proxmox-rest-server/src/worker_task.rs index 5bab4cdc6d0b..d680e242de11 100644 --- a/proxmox-rest-server/src/worker_task.rs +++ b/proxmox-rest-server/src/worker_task.rs @@ -1,3 +1,4 @@ +use std::cell::{Cell, RefCell}; use std::collections::{HashMap, VecDeque}; use std::fs::File; use std::io::{BufRead, BufReader, Read, Write}; @@ -16,17 +17,18 @@ use serde::{Deserialize, Serialize}; use serde_json::{json, Value}; use tokio::signal::unix::SignalKind; use tokio::sync::oneshot; +use tracing::{info, warn}; use proxmox_lang::try_block; +use proxmox_log::{FileLogOptions, FileLogger, LOGGER, WARN_COUNTER}; use proxmox_schema::upid::UPID; use proxmox_sys::fs::{atomic_open_or_create_file, create_path, replace_file, CreateOptions}; use proxmox_sys::linux::procfs; -use proxmox_sys::task_warn; use proxmox_sys::logrotate::{LogRotate, LogRotateFiles}; use proxmox_sys::WorkerTaskContext; -use crate::{CommandSocket, FileLogOptions, FileLogger}; +use crate::CommandSocket; struct TaskListLockGuard(File); @@ -294,7 +296,7 @@ pub fn rotate_task_log_archive( /// removes all task logs that are older than the oldest task entry in the /// task archive -pub fn cleanup_old_tasks(worker: &dyn WorkerTaskContext, compressed: bool) -> Result<(), Error> { +pub fn cleanup_old_tasks(compressed: bool) -> Result<(), Error> { let setup = worker_task_setup()?; let _lock = setup.lock_task_list_files(true)?; @@ -332,7 +334,7 @@ pub fn cleanup_old_tasks(worker: &dyn WorkerTaskContext, compressed: bool) -> Re Ok(files) => files, Err(err) if err.kind() == std::io::ErrorKind::NotFound => continue, Err(err) => { - task_warn!(worker, "could not check task logs in '{:02X}': {}", i, err); + warn!("could not check task logs in '{i:02X}': {err}"); continue; } }; @@ -340,12 +342,7 @@ pub fn cleanup_old_tasks(worker: &dyn WorkerTaskContext, compressed: bool) -> Re let file = match file { Ok(file) => file, Err(err) => { - task_warn!( - worker, - "could not check some task log in '{:02X}': {}", - i, - err - ); + warn!("could not check some task log in '{i:02X}': {err}"); continue; } }; @@ -354,7 +351,7 @@ pub fn cleanup_old_tasks(worker: &dyn WorkerTaskContext, compressed: bool) -> Re let modified = match get_modified(file) { Ok(modified) => modified, Err(err) => { - task_warn!(worker, "error getting mtime for '{:?}': {}", path, err); + warn!("error getting mtime for '{path:?}': {err}"); continue; } }; @@ -364,7 +361,7 @@ pub fn cleanup_old_tasks(worker: &dyn WorkerTaskContext, compressed: bool) -> Re Ok(()) => {} Err(err) if err.kind() == std::io::ErrorKind::NotFound => {} Err(err) => { - task_warn!(worker, "could not remove file '{:?}': {}", path, err) + warn!("could not remove file '{path:?}': {err}") } } } @@ -822,9 +819,7 @@ impl std::fmt::Display for WorkerTask { } struct WorkerTaskData { - logger: FileLogger, progress: f64, // 0..1 - warn_count: u64, pub abort_listeners: Vec>, } @@ -834,7 +829,7 @@ impl WorkerTask { worker_id: Option, auth_id: String, to_stdout: bool, - ) -> Result, Error> { + ) -> Result<(Arc, FileLogger), Error> { let setup = worker_task_setup()?; let upid = UPID::new(worker_type, worker_id, auth_id)?; @@ -857,9 +852,7 @@ impl WorkerTask { upid: upid.clone(), abort_requested: AtomicBool::new(false), data: Mutex::new(WorkerTaskData { - logger, progress: 0.0, - warn_count: 0, abort_listeners: vec![], }), }); @@ -873,7 +866,7 @@ impl WorkerTask { setup.update_active_workers(Some(&upid))?; - Ok(worker) + Ok((worker, logger)) } /// Spawn a new tokio task/future. @@ -888,13 +881,20 @@ impl WorkerTask { F: Send + 'static + FnOnce(Arc) -> T, T: Send + 'static + Future>, { - let worker = WorkerTask::new(worker_type, worker_id, auth_id, to_stdout)?; + let (worker, logger) = WorkerTask::new(worker_type, worker_id, auth_id, to_stdout)?; let upid_str = worker.upid.to_string(); let f = f(worker.clone()); - tokio::spawn(async move { - let result = f.await; - worker.log_result(&result); - }); + + let logger = RefCell::new(logger); + let counter = Cell::new(0); + tokio::spawn(LOGGER.scope(logger, async move { + WARN_COUNTER + .scope(counter, async move { + let result = f.await; + worker.log_result(&result); + }) + .await; + })); Ok(upid_str) } @@ -910,22 +910,27 @@ impl WorkerTask { where F: Send + UnwindSafe + 'static + FnOnce(Arc) -> Result<(), Error>, { - let worker = WorkerTask::new(worker_type, worker_id, auth_id, to_stdout)?; + let (worker, logger) = WorkerTask::new(worker_type, worker_id, auth_id, to_stdout)?; let upid_str = worker.upid.to_string(); let _child = std::thread::Builder::new() .name(upid_str.clone()) .spawn(move || { - let worker1 = worker.clone(); - let result = match std::panic::catch_unwind(move || f(worker1)) { - Ok(r) => r, - Err(panic) => match panic.downcast::<&str>() { - Ok(panic_msg) => Err(format_err!("worker panicked: {}", panic_msg)), - Err(_) => Err(format_err!("worker panicked: unknown type.")), - }, - }; + LOGGER.sync_scope(RefCell::new(logger), || { + WARN_COUNTER.sync_scope(Cell::new(0), || { + let worker1 = worker.clone(); + + let result = match std::panic::catch_unwind(move || f(worker1)) { + Ok(r) => r, + Err(panic) => match panic.downcast::<&str>() { + Ok(panic_msg) => Err(format_err!("worker panicked: {}", panic_msg)), + Err(_) => Err(format_err!("worker panicked: unknown type.")), + }, + }; - worker.log_result(&result); + worker.log_result(&result); + }); + }); }); Ok(upid_str) @@ -933,7 +938,7 @@ impl WorkerTask { /// create state from self and a result pub fn create_state(&self, result: &Result<(), Error>) -> TaskState { - let warn_count = self.data.lock().unwrap().warn_count; + let warn_count = WARN_COUNTER.try_with(Cell::get).unwrap_or(0); let endtime = proxmox_time::epoch_i64(); @@ -964,15 +969,7 @@ impl WorkerTask { /// Log a message. pub fn log_message>(&self, msg: S) { - let mut data = self.data.lock().unwrap(); - data.logger.log(msg); - } - - /// Log a message as warning. - pub fn log_warning>(&self, msg: S) { - let mut data = self.data.lock().unwrap(); - data.logger.log(format!("WARN: {}", msg.as_ref())); - data.warn_count += 1; + info!("{}", msg.as_ref()); } /// Set progress indicator @@ -1035,16 +1032,6 @@ impl WorkerTaskContext for WorkerTask { fn fail_on_shutdown(&self) -> Result<(), Error> { crate::fail_on_shutdown() } - - fn log(&self, level: log::Level, message: &std::fmt::Arguments) { - match level { - log::Level::Error => self.log_warning(message.to_string()), - log::Level::Warn => self.log_warning(message.to_string()), - log::Level::Info => self.log_message(message.to_string()), - log::Level::Debug => self.log_message(format!("DEBUG: {}", message)), - log::Level::Trace => self.log_message(format!("TRACE: {}", message)), - } - } } /// Wait for a locally spanned worker task diff --git a/proxmox-sys/src/worker_task_context.rs b/proxmox-sys/src/worker_task_context.rs index 2c86857c70f7..743ae53fe190 100644 --- a/proxmox-sys/src/worker_task_context.rs +++ b/proxmox-sys/src/worker_task_context.rs @@ -26,9 +26,6 @@ pub trait WorkerTaskContext: Send + Sync { } Ok(()) } - - /// Create a log message for this task. - fn log(&self, level: log::Level, message: &std::fmt::Arguments); } /// Convenience implementation: @@ -48,48 +45,4 @@ impl WorkerTaskContext for std::sync::Arc { fn fail_on_shutdown(&self) -> Result<(), Error> { ::fail_on_shutdown(self) } - - fn log(&self, level: log::Level, message: &std::fmt::Arguments) { - ::log(self, level, message) - } -} - -/// Log an error to a [WorkerTaskContext] -#[macro_export] -macro_rules! task_error { - ($task:expr, $($fmt:tt)+) => {{ - $crate::WorkerTaskContext::log(&*$task, log::Level::Error, &format_args!($($fmt)+)) - }}; -} - -/// Log a warning to a [WorkerTaskContext] -#[macro_export] -macro_rules! task_warn { - ($task:expr, $($fmt:tt)+) => {{ - $crate::WorkerTaskContext::log(&*$task, log::Level::Warn, &format_args!($($fmt)+)) - }}; -} - -/// Log a message to a [WorkerTaskContext] -#[macro_export] -macro_rules! task_log { - ($task:expr, $($fmt:tt)+) => {{ - $crate::WorkerTaskContext::log(&*$task, log::Level::Info, &format_args!($($fmt)+)) - }}; -} - -/// Log a debug message to a [WorkerTaskContext] -#[macro_export] -macro_rules! task_debug { - ($task:expr, $($fmt:tt)+) => {{ - $crate::WorkerTaskContext::log(&*$task, log::Level::Debug, &format_args!($($fmt)+)) - }}; -} - -/// Log a trace message to a [WorkerTaskContext] -#[macro_export] -macro_rules! task_trace { - ($task:expr, $($fmt:tt)+) => {{ - $crate::WorkerTaskContext::log(&*$task, log::Level::Trace, &format_args!($($fmt)+)) - }}; } -- 2.43.0 _______________________________________________ pbs-devel mailing list pbs-devel@lists.proxmox.com https://lists.proxmox.com/cgi-bin/mailman/listinfo/pbs-devel