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)) (No client certificate requested) by lists.proxmox.com (Postfix) with ESMTPS id 85E2699DBE for ; Wed, 11 Oct 2023 16:01:11 +0200 (CEST) Received: from firstgate.proxmox.com (localhost [127.0.0.1]) by firstgate.proxmox.com (Proxmox) with ESMTP id 6C8549F53 for ; Wed, 11 Oct 2023 16:01:11 +0200 (CEST) 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)) (No client certificate requested) by firstgate.proxmox.com (Proxmox) with ESMTPS for ; Wed, 11 Oct 2023 16:01:09 +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 03EEA438AC for ; Wed, 11 Oct 2023 16:01:09 +0200 (CEST) From: Gabriel Goller To: pbs-devel@lists.proxmox.com Date: Wed, 11 Oct 2023 16:01:02 +0200 Message-Id: <20231011140102.273423-3-g.goller@proxmox.com> X-Mailer: git-send-email 2.39.2 In-Reply-To: <20231011140102.273423-1-g.goller@proxmox.com> References: <20231011140102.273423-1-g.goller@proxmox.com> MIME-Version: 1.0 Content-Transfer-Encoding: 8bit X-SPAM-LEVEL: Spam detection results: 0 AWL -0.352 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] [RFC proxmox 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: Wed, 11 Oct 2023 14:01:11 -0000 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 | 89 +++++++++++++++ .../src/file_logger.rs | 2 +- proxmox-log/src/lib.rs | 36 ++++++ proxmox-log/src/syslog_layer.rs | 78 +++++++++++++ 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 | 108 ++++++++++-------- proxmox-router/Cargo.toml | 2 + proxmox-sys/src/worker_task_context.rs | 47 -------- 17 files changed, 382 insertions(+), 104 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..1a167f4 --- /dev/null +++ b/proxmox-log/src/file_layer.rs @@ -0,0 +1,89 @@ +use std::cell::RefCell; +use tracing::error; +use tracing::field::Field; +use tracing::field::Visit; +use tracing::Event; +use tracing::Level; +use tracing::Subscriber; +use tracing_subscriber::layer::Context; +use tracing_subscriber::Layer; + +use crate::FileLogger; + +tokio::task_local! { + pub static LOGGER: RefCell>; + pub static WARN_COUNTER: RefCell>; +} + +pub struct FilelogLayer {} + +impl FilelogLayer { + pub fn new() -> Self { + Self {} + } +} + +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)); + + let logger_exists = LOGGER.try_with(|logger| { + let mut l = logger.borrow_mut(); + let log = l.as_mut(); + if let Some(l) = log { + log_to_file(l, event.metadata().level(), buf); + } else { + error!("FileLogger not found"); + } + }); + if let Err(e) = logger_exists { + error!( + "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| { + if let Some(v) = c { + Some(v.to_owned() + 1) + } else { + None + } + }); + logger.log(buf.clone()); + }); + if let Err(e) = counter_exists { + error!("Error getting the warning_counter for the logger: {}", e) + } + } + &Level::INFO => logger.log(buf.clone()), + &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)); + } + } +} 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..0c101b7 --- /dev/null +++ b/proxmox-log/src/lib.rs @@ -0,0 +1,36 @@ +//! # Proxmox logging infrastructure +use crate::syslog_layer::SyslogLayer; +use file_layer::FilelogLayer; +use std::env; +use tracing_log::LogTracer; +use tracing_subscriber::filter::{filter_fn, LevelFilter}; +use tracing_subscriber::prelude::*; + +pub mod file_layer; +mod file_logger; +pub use file_logger::{FileLogOptions, FileLogger}; + +mod syslog_layer; + +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 registry = tracing_subscriber::registry() + .with(FilelogLayer::new().with_filter(filter_fn(|metadata| { + metadata.fields().field("tasklog").is_some() + }))) + .with(SyslogLayer::new(application_name.to_string()).with_filter(log_level)); + + tracing::subscriber::set_global_default(registry)?; + + LogTracer::init()?; + Ok(()) +} diff --git a/proxmox-log/src/syslog_layer.rs b/proxmox-log/src/syslog_layer.rs new file mode 100644 index 0000000..50ea145 --- /dev/null +++ b/proxmox-log/src/syslog_layer.rs @@ -0,0 +1,78 @@ +use std::fmt; +use std::sync::Arc; +use std::sync::Mutex; +use syslog::Formatter3164; +use syslog::Logger; +use syslog::LoggerBackend; +use tracing::field::Field; +use tracing::field::Visit; +use tracing::Event; +use tracing::Level; +use tracing::Subscriber; +use tracing_subscriber::layer::Context; +use tracing_subscriber::Layer; + +pub struct SyslogLayer { + logger: Arc>>, +} + +impl SyslogLayer { + pub fn new(application_name: String) -> Self { + let mut formatter = Formatter3164::default(); + formatter.facility = syslog::Facility::LOG_DAEMON; + formatter.process = application_name; + + // unwrap because if the (syslog) logging is not working, we shut down + let backend = syslog::unix(formatter.clone()) + .map(|logger: Logger| logger.backend) + .map_err(|e| { + anyhow::Error::new(std::io::Error::new( + std::io::ErrorKind::Other, + e.description(), + )) + }) + .unwrap(); + + let logger = Arc::new(Mutex::new(Logger { formatter, backend })); + + 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 { + log::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)); + } + } +} 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..f7b8396 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::file_layer::{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}; 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,21 @@ 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(Some(logger)); + let counter = RefCell::new(Some(0)); tokio::spawn(async move { - let result = f.await; - worker.log_result(&result); + LOGGER.scope(logger, async move { + WARN_COUNTER.scope(counter, async move { + let result = f.await; + worker.log_result(&result); + }) + .await; + }) + .await; }); Ok(upid_str) @@ -895,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(Some(logger)), || { + WARN_COUNTER.sync_scope(RefCell::new(Some(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) @@ -918,7 +938,13 @@ 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| { + if let Some(v) = counter.borrow_mut().as_mut() { + warn_count = v.to_owned(); + } + }); let endtime = proxmox_time::epoch_i64(); @@ -949,15 +975,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 +1038,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-router/Cargo.toml b/proxmox-router/Cargo.toml index c53ccd0..2460999 100644 --- a/proxmox-router/Cargo.toml +++ b/proxmox-router/Cargo.toml @@ -19,6 +19,8 @@ percent-encoding.workspace = true serde_json.workspace = true serde.workspace = true unicode-width ="0.1.8" +syslog = "6" +log = "0.4.17" # cli: tokio = { workspace = true, features = [], optional = true } 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