From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from ronja.mits.lan by ronja.mits.lan with LMTP id SMuVOAdUeWbtYwAAxxbTJA (envelope-from ); Mon, 24 Jun 2024 13:09:59 +0200 Received: from proxmox-new.maurer-it.com (unknown [192.168.2.33]) by ronja.mits.lan (Postfix) with ESMTPS id CCFF3F6462B; Mon, 24 Jun 2024 13:09:59 +0200 (CEST) Received: from proxmox-new.maurer-it.com (localhost.localdomain [127.0.0.1]) by proxmox-new.maurer-it.com (Proxmox) with ESMTP id B042F485BB; Mon, 24 Jun 2024 13:09:59 +0200 (CEST) Received: from firstgate.proxmox.com (firstgate.proxmox.com [212.224.123.68]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (4096 bits)) (No client certificate requested) by proxmox-new.maurer-it.com (Proxmox) with ESMTPS; Mon, 24 Jun 2024 13:09:57 +0200 (CEST) Received: from firstgate.proxmox.com (localhost [127.0.0.1]) by firstgate.proxmox.com (Proxmox) with ESMTP id 52B2F34CE7; Mon, 24 Jun 2024 13:09:56 +0200 (CEST) Message-ID: <3486aeae-4ddc-4b16-9b11-5989abc52304@proxmox.com> Date: Mon, 24 Jun 2024 13:09:50 +0200 MIME-Version: 1.0 User-Agent: Mozilla Thunderbird To: Proxmox Backup Server development discussion , Gabriel Goller References: <20240613135623.279167-1-g.goller@proxmox.com> <20240613135623.279167-3-g.goller@proxmox.com> Content-Language: de-AT, en-US From: Lukas Wagner In-Reply-To: <20240613135623.279167-3-g.goller@proxmox.com> Subject: Re: [pbs-devel] [PATCH proxmox v5 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 Content-Type: text/plain; charset="us-ascii" Content-Transfer-Encoding: 7bit Errors-To: pbs-devel-bounces@lists.proxmox.com Sender: "pbs-devel" X-SPAM-LEVEL: Spam detection results: 0 DMARC_MISSING 0.1 Missing DMARC policy KAM_DMARC_STATUS 0.01 Test Rule for DKIM or SPF Failure with Strict Alignment KAM_LAZY_DOMAIN_SECURITY 1 Sending domain does not have any anti-forgery methods MAILING_LIST_MULTI -2 Multiple indicators imply a widely-seen list manager RCVD_IN_DNSWL_MED -2.3 Sender listed at https://www.dnswl.org/, medium trust SPF_HELO_NONE 0.001 SPF: HELO does not publish an SPF Record SPF_NONE 0.001 SPF: sender does not publish an SPF Record 2 nits inline On 2024-06-13 15:56, Gabriel Goller wrote: > 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. > > Signed-off-by: Gabriel Goller > --- > 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 | 104 ++++++++--------- > proxmox-sys/src/worker_task_context.rs | 47 -------- > 6 files changed, 56 insertions(+), 252 deletions(-) > delete mode 100644 proxmox-rest-server/src/file_logger.rs > > diff --git a/proxmox-rest-server/src/api_config.rs b/proxmox-rest-server/src/api_config.rs > index eaece05a..5b7a2a4f 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 2bb1fac6..00000000 > --- 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 ce9e4f15..e8866366 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 39ae9a18..3a3c287c 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 5bab4cdc..58537f54 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}; > @@ -12,21 +13,23 @@ use futures::*; > use lazy_static::lazy_static; > use nix::fcntl::OFlag; > use once_cell::sync::OnceCell; > +use proxmox_log::{LOGGER, WARN_COUNTER}; Nit: Order of imports, let's put this import to the other proxmox_* imports below > 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}; > 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 +297,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 +335,10 @@ 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!( > + tasklog = true, > + "could not check task logs in '{:02X}': {}", i, err > + ); > continue; > } > }; > @@ -340,11 +346,9 @@ 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!( > + tasklog = true, > + "could not check some task log in '{:02X}': {}", i err Nit: You could inline these vars if you edit these lines any way. > ); > continue; > } > @@ -354,7 +358,10 @@ 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!( > + tasklog = true, > + "error getting mtime for '{:?}': {}", path, err > + ); > continue; > } > }; > @@ -364,7 +371,10 @@ 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!( > + tasklog = true, > + "could not remove file '{:?}': {}", path, err > + ) > } > } > } > @@ -822,9 +832,7 @@ impl std::fmt::Display for WorkerTask { > } > > struct WorkerTaskData { > - logger: FileLogger, > progress: f64, // 0..1 > - warn_count: u64, > pub abort_listeners: Vec>, > } > > @@ -834,7 +842,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 +865,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 +879,7 @@ impl WorkerTask { > > setup.update_active_workers(Some(&upid))?; > > - Ok(worker) > + Ok((worker, logger)) > } > > /// Spawn a new tokio task/future. > @@ -888,13 +894,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 +923,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 +951,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 +982,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!(tasklog = true, "{}", msg.as_ref()); > } > > /// Set progress indicator > @@ -1035,16 +1045,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 2c86857c..743ae53f 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)+)) > - }}; > } -- - Lukas _______________________________________________ pbs-devel mailing list pbs-devel@lists.proxmox.com https://lists.proxmox.com/cgi-bin/mailman/listinfo/pbs-devel