From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: 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 (2048 bits) server-digest SHA256) (No client certificate requested) by lists.proxmox.com (Postfix) with ESMTPS id 185419E8F7 for ; Thu, 2 Nov 2023 14:43:59 +0100 (CET) Received: from firstgate.proxmox.com (localhost [127.0.0.1]) by firstgate.proxmox.com (Proxmox) with ESMTP id F0B0E1189E for ; Thu, 2 Nov 2023 14:43:58 +0100 (CET) Received: from proxmox-new.maurer-it.com (proxmox-new.maurer-it.com [94.136.29.106]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (2048 bits) server-digest SHA256) (No client certificate requested) by firstgate.proxmox.com (Proxmox) with ESMTPS for ; Thu, 2 Nov 2023 14:43:54 +0100 (CET) Received: from proxmox-new.maurer-it.com (localhost.localdomain [127.0.0.1]) by proxmox-new.maurer-it.com (Proxmox) with ESMTP id 8F74743C03 for ; Thu, 2 Nov 2023 14:43:54 +0100 (CET) Date: Thu, 2 Nov 2023 14:43:50 +0100 From: Wolfgang Bumiller To: Gabriel Goller Cc: pbs-devel@lists.proxmox.com Message-ID: References: <20231025135325.198073-1-g.goller@proxmox.com> <20231025135325.198073-3-g.goller@proxmox.com> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: <20231025135325.198073-3-g.goller@proxmox.com> X-SPAM-LEVEL: Spam detection results: 0 AWL 0.103 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 T_SCC_BODY_TEXT_LINE -0.01 - URIBL_BLOCKED 0.001 ADMINISTRATOR NOTICE: The query to URIBL was blocked. See http://wiki.apache.org/spamassassin/DnsBlocklists#dnsbl-block for more information. [gnu.org, rest.rs, proxmox.com, lib.rs] Subject: Re: [pbs-devel] [RFC proxmox v2 2/2] proxmox-log: added tracing infra 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: , X-List-Received-Date: Thu, 02 Nov 2023 13:43:59 -0000 On Wed, Oct 25, 2023 at 03:53:25PM +0200, Gabriel Goller wrote: > Added the `proxmox_log` crate which includes the new logging infra. > Exports the `init_logger` function, which creates the `tracing` logger > that includes the default Subscriber and two custom layers. The first > layer is the syslog layer, which uses the `syslog` crate. The second > layer is the `file_layer` which uses the original `FileLogger` and > writes to a file (the tasklog). This last layer stores the `FileLogger` > as a `tokio::task_local` variable, which gets initialized at `spawn` or > `new_thread` in the `WorkerTask`. > > Signed-off-by: Gabriel Goller > --- > Cargo.toml | 6 + > proxmox-log/Cargo.toml | 23 +++ > proxmox-log/debian/changelog | 5 + > proxmox-log/debian/control | 53 +++++++ > proxmox-log/debian/copyright | 18 +++ > proxmox-log/debian/debcargo.toml | 7 + > proxmox-log/src/file_layer.rs | 139 ++++++++++++++++++ > .../src/file_logger.rs | 2 +- > proxmox-log/src/lib.rs | 50 +++++++ > proxmox-log/src/syslog_layer.rs | 111 ++++++++++++++ > proxmox-rest-server/Cargo.toml | 2 + > proxmox-rest-server/src/api_config.rs | 3 +- > proxmox-rest-server/src/lib.rs | 3 - > proxmox-rest-server/src/rest.rs | 4 +- > proxmox-rest-server/src/worker_task.rs | 120 ++++++++------- > proxmox-sys/src/worker_task_context.rs | 47 ------ > 16 files changed, 488 insertions(+), 105 deletions(-) > create mode 100644 proxmox-log/Cargo.toml > create mode 100644 proxmox-log/debian/changelog > create mode 100644 proxmox-log/debian/control > create mode 100644 proxmox-log/debian/copyright > create mode 100644 proxmox-log/debian/debcargo.toml > create mode 100644 proxmox-log/src/file_layer.rs > rename {proxmox-rest-server => proxmox-log}/src/file_logger.rs (98%) > create mode 100644 proxmox-log/src/lib.rs > create mode 100644 proxmox-log/src/syslog_layer.rs > > diff --git a/Cargo.toml b/Cargo.toml > index 265f5c9..246d6e4 100644 > --- a/Cargo.toml > +++ b/Cargo.toml > @@ -13,6 +13,7 @@ members = [ > "proxmox-io", > "proxmox-lang", > "proxmox-ldap", > + "proxmox-log", > "proxmox-login", > "proxmox-metrics", > "proxmox-notify", > @@ -81,10 +82,14 @@ tokio = "1.6" > tokio-openssl = "0.6.1" > tokio-stream = "0.1.0" > tower-service = "0.3.0" > +tracing = "0.1" > +tracing-log = { version = "0.1.3", default-features = false } > +tracing-subscriber = "0.3.16" > url = "2.2" > walkdir = "2" > webauthn-rs = "0.3" > zstd = { version = "0.12", features = [ "bindgen" ] } > +syslog = "6" > > # workspace dependencies > proxmox-api-macro = { version = "1.0.6", path = "proxmox-api-macro" } > @@ -95,6 +100,7 @@ proxmox-http-error = { version = "0.1.0", path = "proxmox-http-error" } > proxmox-human-byte = { version = "0.1.0", path = "proxmox-human-byte" } > proxmox-io = { version = "1.0.0", path = "proxmox-io" } > proxmox-lang = { version = "1.1", path = "proxmox-lang" } > +proxmox-log= { version = "0.1.0", path = "proxmox-log" } > proxmox-login = { version = "0.1.0", path = "proxmox-login" } > proxmox-rest-server = { version = "0.4.0", path = "proxmox-rest-server" } > proxmox-router = { version = "2.1.1", path = "proxmox-router" } > diff --git a/proxmox-log/Cargo.toml b/proxmox-log/Cargo.toml > new file mode 100644 > index 0000000..e05b0be > --- /dev/null > +++ b/proxmox-log/Cargo.toml > @@ -0,0 +1,23 @@ > +[package] > +name = "proxmox-log" > +version = "0.1.0" > +authors.workspace = true > +edition.workspace = true > +license.workspace = true > +repository.workspace = true > +description = "Logging infrastructure for proxmox" > + > +exclude.workspace = true > + > +[dependencies] > +anyhow.workspace = true > +syslog.workspace = true > +nix.workspace = true > +log.workspace = true > +tracing.workspace = true > +tracing-subscriber.workspace = true > +tracing-log.workspace = true > +tokio = { workspace = true, features = ["rt-multi-thread"] } > +proxmox-time.workspace = true > +proxmox-sys.workspace = true > + > diff --git a/proxmox-log/debian/changelog b/proxmox-log/debian/changelog > new file mode 100644 > index 0000000..aaf8073 > --- /dev/null > +++ b/proxmox-log/debian/changelog > @@ -0,0 +1,5 @@ > +rust-proxmox-log (0.1.0-3) UNRELEASED; urgency=medium > + > + * Initial release > + > + -- Gabriel Goller Wed, 11 Oct 2023 15:13:58 +0200 > diff --git a/proxmox-log/debian/control b/proxmox-log/debian/control > new file mode 100644 > index 0000000..4f22ecb > --- /dev/null > +++ b/proxmox-log/debian/control > @@ -0,0 +1,53 @@ > +Source: rust-proxmox-log > +Section: rust > +Priority: optional > +Build-Depends: debhelper (>= 12), > + dh-cargo (>= 25), > + cargo:native , > + rustc:native , > + libstd-rust-dev , > + librust-anyhow-1+default-dev , > + librust-log-0.4+default-dev (>= 0.4.17-~~) , > + librust-nix-0.26+default-dev (>= 0.26.1-~~) , > + librust-proxmox-sys-0.5+default-dev , > + librust-proxmox-time-1+default-dev (>= 1.1.4-~~) , > + librust-syslog-6+default-dev , > + librust-tokio-1+default-dev (>= 1.6-~~) , > + librust-tokio-1+rt-multi-thread-dev (>= 1.6-~~) , > + librust-tracing-0.1+default-dev , > + librust-tracing-log-0.1-dev (>= 0.1.3-~~) , > + librust-tracing-subscriber-0.3+default-dev (>= 0.3.16-~~) > +Maintainer: Proxmox Support Team > +Standards-Version: 4.6.1 > +Vcs-Git: git://git.proxmox.com/git/proxmox.git > +Vcs-Browser: https://git.proxmox.com/?p=proxmox.git > +X-Cargo-Crate: proxmox-log > +Rules-Requires-Root: no > + > +Package: librust-proxmox-log-dev > +Architecture: any > +Multi-Arch: same > +Depends: > + ${misc:Depends}, > + librust-anyhow-1+default-dev, > + librust-log-0.4+default-dev (>= 0.4.17-~~), > + librust-nix-0.26+default-dev (>= 0.26.1-~~), > + librust-proxmox-sys-0.5+default-dev, > + librust-proxmox-time-1+default-dev (>= 1.1.4-~~), > + librust-syslog-6+default-dev, > + librust-tokio-1+default-dev (>= 1.6-~~), > + librust-tokio-1+rt-multi-thread-dev (>= 1.6-~~), > + librust-tracing-0.1+default-dev, > + librust-tracing-log-0.1-dev (>= 0.1.3-~~), > + librust-tracing-subscriber-0.3+default-dev (>= 0.3.16-~~) > +Provides: > + librust-proxmox-log+default-dev (= ${binary:Version}), > + librust-proxmox-log-0-dev (= ${binary:Version}), > + librust-proxmox-log-0+default-dev (= ${binary:Version}), > + librust-proxmox-log-0.1-dev (= ${binary:Version}), > + librust-proxmox-log-0.1+default-dev (= ${binary:Version}), > + librust-proxmox-log-0.1.0-dev (= ${binary:Version}), > + librust-proxmox-log-0.1.0+default-dev (= ${binary:Version}) > +Description: Logging infrastructure for proxmox - Rust source code > + This package contains the source for the Rust proxmox-log crate, packaged by > + debcargo for use with cargo and dh-cargo. > diff --git a/proxmox-log/debian/copyright b/proxmox-log/debian/copyright > new file mode 100644 > index 0000000..0d9eab3 > --- /dev/null > +++ b/proxmox-log/debian/copyright > @@ -0,0 +1,18 @@ > +Format: https://www.debian.org/doc/packaging-manuals/copyright-format/1.0/ > + > +Files: > + * > +Copyright: 2019 - 2023 Proxmox Server Solutions GmbH > +License: AGPL-3.0-or-later > + This program is free software: you can redistribute it and/or modify it under > + the terms of the GNU Affero General Public License as published by the Free > + Software Foundation, either version 3 of the License, or (at your option) any > + later version. > + . > + This program is distributed in the hope that it will be useful, but WITHOUT > + ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or FITNESS > + FOR A PARTICULAR PURPOSE. See the GNU Affero General Public License for more > + details. > + . > + You should have received a copy of the GNU Affero General Public License along > + with this program. If not, see . > diff --git a/proxmox-log/debian/debcargo.toml b/proxmox-log/debian/debcargo.toml > new file mode 100644 > index 0000000..b7864cd > --- /dev/null > +++ b/proxmox-log/debian/debcargo.toml > @@ -0,0 +1,7 @@ > +overlay = "." > +crate_src_path = ".." > +maintainer = "Proxmox Support Team " > + > +[source] > +vcs_git = "git://git.proxmox.com/git/proxmox.git" > +vcs_browser = "https://git.proxmox.com/?p=proxmox.git" > diff --git a/proxmox-log/src/file_layer.rs b/proxmox-log/src/file_layer.rs > new file mode 100644 > index 0000000..814832c > --- /dev/null > +++ b/proxmox-log/src/file_layer.rs > @@ -0,0 +1,139 @@ > +use std::sync::Arc; > +use std::sync::Mutex; > + > +use tracing::error; > +use tracing::field::Field; > +use tracing::field::Visit; > +use tracing::span; > +use tracing::Event; > +use tracing::Level; > +use tracing::Metadata; > +use tracing::Subscriber; > +use tracing_subscriber::layer::Context; > +use tracing_subscriber::layer::Filter; > +use tracing_subscriber::registry::LookupSpan; > +use tracing_subscriber::Layer; > + > +use crate::FileLogger; > +use crate::LOGGER; > +use crate::WARN_COUNTER; > + > +pub struct FilelogLayer; > + > +impl FilelogLayer { > + pub fn new() -> Self { > + Self {} > + } > +} > + > +impl Default for FilelogLayer { > + fn default() -> Self { > + Self::new() > + } > +} > + > +impl Layer for FilelogLayer { > + fn on_event(&self, event: &Event<'_>, _ctx: Context<'_, S>) { > + let mut buf = String::new(); > + > + event.record(&mut EventVisitor::new(&mut buf)); I'd argue the above 2 lines should be part of the closure below, otherwise in the error case you just produce a string to throw away. > + > + let logger_exists = LOGGER.try_with(|logger| { > + log_to_file(&mut logger.borrow_mut(), event.metadata().level(), buf); > + }); > + if let Err(e) = logger_exists { > + error!( Is it wise to call log functions from within log handlers? ;-) > + "Error getting the logger from the task-local storage: {}", > + e > + ) > + } > + } > +} > + > +fn log_to_file(logger: &mut FileLogger, level: &Level, buf: String) { > + match level { > + &Level::ERROR | &Level::WARN => { > + let counter_exists = WARN_COUNTER.try_with(|counter| { > + counter.replace_with(|c| c.to_owned() + 1); > + }); > + logger.log(buf); > + if let Err(e) = counter_exists { > + error!("Error getting the warning_counter for the logger: {}", e) > + } > + } > + &Level::INFO => logger.log(buf), > + &Level::DEBUG => logger.log(format!("DEBUG: {}", buf)), > + &Level::TRACE => logger.log(format!("TRACE: {}", buf)), > + }; > +} > + > +struct EventVisitor<'a> { > + buf: &'a mut String, > +} > + > +impl<'a> EventVisitor<'a> { > + fn new(buf: &'a mut String) -> Self { > + Self { buf } > + } > +} > + > +impl Visit for EventVisitor<'_> { > + fn record_debug(&mut self, field: &Field, value: &dyn std::fmt::Debug) { > + if field.name() == "message" { > + self.buf.push_str(&format!("{:?}", value)); > + } > + } > +} > + > +pub struct WorkerTaskFilter { > + in_worker_task: Arc>, AFAICT you only have locks which are shortlived to set/clear/check this value. For such a thing you can use `Arc` and get rid of all the error handling. > +} > + > +impl WorkerTaskFilter { > + pub fn new(in_worker_task: Arc>) -> WorkerTaskFilter { > + WorkerTaskFilter { in_worker_task } > + } > +} > + > +impl LookupSpan<'a>> Filter for WorkerTaskFilter { > + fn on_enter(&self, id: &span::Id, ctx: Context<'_, S>) { > + let metadata = ctx.metadata(id); > + if let Some(m) = metadata { > + if m.name() == "worker_task" { I'm not so happy with this. Now each time we poll a worker task we go through this layer system which uses string comparison to know whether we're currently in a worker task, for something that is actually rather static in the code. I'd much prefer a simply custom `Future` wrapping the worker task's future and setting this flag for the duration of the `poll()` method. This just seems like a whole lot of overhead we don't need for such simple functionality. Also, the `on_enter` and `on_exit` methods make it look like you could easily enter and exit this type of span, but that's not the case. `on_exit` always stores `false`, so nested spans temporarily disabling and enabling the worker task log would just end up with a messed up state (this would need to be a counter...). As for the lock, with an atomic the code below would just be: self.in_worker_task.store(true, Ordering::Relaxed); > + let flag = self.in_worker_task.lock(); > + match flag { > + Ok(mut flag) => *flag = true, > + Err(e) => error!("Failed to lock `in_worker_task` flag: {e}"), > + }; > + } > + } > + } > + > + fn on_exit(&self, id: &span::Id, ctx: Context<'_, S>) { > + let metadata = ctx.metadata(id); > + if let Some(m) = metadata { > + if m.name() == "worker_task" { > + let flag = self.in_worker_task.lock(); > + match flag { > + Ok(mut flag) => *flag = false, > + Err(e) => error!("Failed to lock `in_worker_task` flag: {e}"), > + }; > + } > + } > + } > + > + fn enabled(&self, meta: &Metadata<'_>, _cx: &Context<'_, S>) -> bool { > + if !meta.is_span() { > + let in_worker_task = self.in_worker_task.lock(); > + match in_worker_task { > + Ok(flag) => *flag, > + Err(e) => { > + error!("Failed to lock `in_worker_task` flag: {e}"); > + true > + } > + } > + } else { > + true > + } > + } > +} > diff --git a/proxmox-rest-server/src/file_logger.rs b/proxmox-log/src/file_logger.rs > similarity index 98% > rename from proxmox-rest-server/src/file_logger.rs > rename to proxmox-log/src/file_logger.rs > index 2bb1fac..c7e1d64 100644 > --- a/proxmox-rest-server/src/file_logger.rs > +++ b/proxmox-log/src/file_logger.rs > @@ -30,7 +30,7 @@ pub struct FileLogOptions { > /// #### Example: > /// ``` > /// # use anyhow::{bail, format_err, Error}; > -/// use proxmox_rest_server::{flog, FileLogger, FileLogOptions}; > +/// use proxmox_log::{flog, FileLogger, FileLogOptions}; > /// > /// # std::fs::remove_file("test.log"); > /// let options = FileLogOptions { > diff --git a/proxmox-log/src/lib.rs b/proxmox-log/src/lib.rs > new file mode 100644 > index 0000000..2409f81 > --- /dev/null > +++ b/proxmox-log/src/lib.rs > @@ -0,0 +1,50 @@ > +//! # Proxmox logging infrastructure > +use crate::syslog_layer::SyslogLayer; > +use file_layer::{FilelogLayer, WorkerTaskFilter}; > +use std::cell::RefCell; > +use std::env; > +use std::sync::{Arc, Mutex}; > +use syslog_layer::InvertedWorkerTaskFilter; > +use tracing_log::{AsLog, LogTracer}; > +use tracing_subscriber::filter::LevelFilter; > +use tracing_subscriber::prelude::*; > + > +pub mod file_layer; > +mod file_logger; > +pub use file_logger::{FileLogOptions, FileLogger}; > + > +mod syslog_layer; > + > +tokio::task_local! { > + pub static LOGGER: RefCell; > + pub static WARN_COUNTER: RefCell; > +} > + > +pub fn init_logger( > + env_var_name: &str, > + default_log_level: LevelFilter, > + application_name: &str, > +) -> Result<(), anyhow::Error> { > + let mut log_level = default_log_level; > + if let Ok(v) = env::var(env_var_name) { > + if let Ok(l) = v.parse::() { > + log_level = l; > + } > + } > + let in_worker_task = Arc::new(Mutex::new(false)); > + let registry = tracing_subscriber::registry() > + .with( > + SyslogLayer::new(application_name.to_string()) > + .with_filter(log_level) > + .with_filter(InvertedWorkerTaskFilter::new(in_worker_task.clone())), > + ) > + .with( > + FilelogLayer::new() > + .with_filter(log_level) > + .with_filter(WorkerTaskFilter::new(in_worker_task)), > + ); > + > + tracing::subscriber::set_global_default(registry)?; > + LogTracer::init_with_filter(log_level.as_log())?; > + Ok(()) > +} > diff --git a/proxmox-log/src/syslog_layer.rs b/proxmox-log/src/syslog_layer.rs > new file mode 100644 > index 0000000..b8eb5f7 > --- /dev/null > +++ b/proxmox-log/src/syslog_layer.rs > @@ -0,0 +1,111 @@ > +use std::fmt; > +use std::sync::Arc; > +use std::sync::Mutex; > +use syslog::Formatter3164; > +use syslog::Logger; > +use syslog::LoggerBackend; > +use tracing::error; > +use tracing::field::Field; > +use tracing::field::Visit; > +use tracing::Event; > +use tracing::Level; > +use tracing::Metadata; > +use tracing::Subscriber; > +use tracing_subscriber::layer::Context; > +use tracing_subscriber::layer::Filter; > +use tracing_subscriber::registry::LookupSpan; > +use tracing_subscriber::Layer; > + > +pub struct SyslogLayer { > + logger: Arc>>, > +} > + > +impl SyslogLayer { > + pub fn new(application_name: String) -> Self { > + let formatter = Formatter3164 { > + facility: syslog::Facility::LOG_DAEMON, > + process: application_name, > + ..Formatter3164::default() > + }; > + > + // we panic here if we can't initialize the syslogger > + let logger = syslog::unix(formatter) > + .map_err(|e| { > + anyhow::Error::new(std::io::Error::new( > + std::io::ErrorKind::Other, > + e.description(), > + )) > + }) > + .unwrap(); > + > + let logger = Arc::new(Mutex::new(logger)); > + > + Self { logger } > + } > +} > + > +impl Layer for SyslogLayer { > + fn on_event(&self, event: &Event<'_>, _ctx: Context<'_, S>) { > + let mut buf = String::new(); > + > + event.record(&mut EventVisitor::new(&mut buf)); > + > + let mut logger = self.logger.lock().unwrap(); > + let succes = match *event.metadata().level() { > + Level::ERROR => logger.err(buf), > + Level::WARN => logger.warning(buf), > + Level::INFO => logger.info(buf), > + Level::DEBUG => logger.debug(buf), > + Level::TRACE => logger.debug(buf), > + }; > + if let Err(err) = succes { > + tracing::error!("{}", err.description()); > + } > + } > +} > + > +struct EventVisitor<'a> { > + buf: &'a mut String, > +} > + > +impl<'a> EventVisitor<'a> { > + fn new(buf: &'a mut String) -> Self { > + Self { buf } > + } > +} > + > +impl Visit for EventVisitor<'_> { > + fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) { > + if field.name() == "message" { > + self.buf.push_str(&format!("{:?}", value)); String implements fmt::Write. You can use std::fmt::Write as _; let _ = write!(state.buf, "{value:?}"); it's possible for this to be more efficient since it does not enforce the creation of a separate allocated string. > + } > + } > +} > + > +pub struct InvertedWorkerTaskFilter { > + in_worker_task: Arc>, > +} > + > +impl InvertedWorkerTaskFilter { > + pub fn new(in_worker_task: Arc>) -> InvertedWorkerTaskFilter { > + InvertedWorkerTaskFilter { in_worker_task } > + } > +} > + > +impl LookupSpan<'lookup>> Filter for InvertedWorkerTaskFilter { > + fn enabled(&self, meta: &Metadata<'_>, _cx: &Context<'_, S>) -> bool { > + // If we get an error, always log to the syslog as well > + if !meta.is_span() && *meta.level() != tracing::Level::ERROR { > + let in_worker_task = self.in_worker_task.lock(); > + match in_worker_task { > + Ok(flag) => !*flag, > + Err(e) => { > + error!("Failed to lock `in_worker_task` flag: {e}"); > + true > + } > + } > + } else { > + true > + } > + } > +} > diff --git a/proxmox-rest-server/Cargo.toml b/proxmox-rest-server/Cargo.toml > index 8daf1d3..a444941 100644 > --- a/proxmox-rest-server/Cargo.toml > +++ b/proxmox-rest-server/Cargo.toml > @@ -34,6 +34,7 @@ tokio-openssl.workspace = true > tokio-stream.workspace = true > tower-service.workspace = true > url.workspace = true > +tracing.workspace = true > > proxmox-async.workspace = true > proxmox-compression.workspace = true > @@ -44,6 +45,7 @@ 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 ad9a811..cf14c8f 100644 > --- a/proxmox-rest-server/src/api_config.rs > +++ b/proxmox-rest-server/src/api_config.rs > @@ -9,11 +9,12 @@ use http::{HeaderMap, Method}; > use hyper::http::request::Parts; > use hyper::{Body, Response}; > > +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/lib.rs b/proxmox-rest-server/src/lib.rs > index bc5be01..9c16065 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}; > > diff --git a/proxmox-rest-server/src/rest.rs b/proxmox-rest-server/src/rest.rs > index 2ccd4d5..9ad01a5 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 54b6bc2..5a36350 100644 > --- a/proxmox-rest-server/src/worker_task.rs > +++ b/proxmox-rest-server/src/worker_task.rs > @@ -1,3 +1,4 @@ > +use std::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}; > use serde::{Deserialize, Serialize}; > use serde_json::{json, Value}; > use tokio::signal::unix::SignalKind; > use tokio::sync::oneshot; > +use tracing::{info, warn, Instrument, Level}; > > 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); > > @@ -274,7 +277,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)?; > @@ -312,7 +315,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; > } > }; > @@ -320,11 +326,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 > ); > continue; > } > @@ -334,7 +338,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; > } > }; > @@ -344,7 +351,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 > + ) > } > } > } > @@ -796,9 +806,7 @@ impl std::fmt::Display for WorkerTask { > } > > struct WorkerTaskData { > - logger: FileLogger, > progress: f64, // 0..1 > - warn_count: u64, > pub abort_listeners: Vec>, > } > > @@ -808,7 +816,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)?; > @@ -842,9 +850,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![], > }), > }); > @@ -858,7 +864,7 @@ impl WorkerTask { > > setup.update_active_workers(Some(&upid))?; > > - Ok(worker) > + Ok((worker, logger)) > } > > /// Spawn a new tokio task/future. > @@ -873,12 +879,28 @@ 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()); > + > + let logger = RefCell::new(logger); > + let counter = RefCell::new(0); > tokio::spawn(async move { > - let result = f.await; > - worker.log_result(&result); > + let span = tracing::span!(Level::INFO, "worker_task"); > + async move { > + LOGGER > + .scope(logger, async move { > + WARN_COUNTER > + .scope(counter, async move { > + let result = f.await; > + worker.log_result(&result); > + }) > + .await; > + }) > + .await; > + } > + .instrument(span) ^ This is what I meant above which I would replace with a manually written `Future` setting up the flag. > + .await; > }); > > Ok(upid_str) > @@ -895,22 +917,32 @@ 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.")), > - }, > - }; > - > - worker.log_result(&result); > + let span = tracing::span!(Level::INFO, "worker_task"); > + span.in_scope(|| { > + LOGGER.sync_scope(RefCell::new(logger), || { > + WARN_COUNTER.sync_scope(RefCell::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); > + }); > + }); > + }); > }); > > Ok(upid_str) > @@ -918,7 +950,11 @@ 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 mut warn_count: u64 = 0; > + > + let _ = WARN_COUNTER.try_with(|counter| { > + warn_count = counter.borrow_mut().to_owned(); > + }); > > let endtime = proxmox_time::epoch_i64(); > > @@ -949,15 +985,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 > @@ -1020,16 +1048,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 2c86857..743ae53 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.39.2 > > > > _______________________________________________ > pbs-devel mailing list > pbs-devel@lists.proxmox.com > https://lists.proxmox.com/cgi-bin/mailman/listinfo/pbs-devel > >