[pbs-devel] [RFC proxmox v2 2/2] proxmox-log: added tracing infra
Gabriel Goller
g.goller at proxmox.com
Wed Oct 25 15:53:25 CEST 2023
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 <g.goller at proxmox.com>
---
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 <ggoller at luna.proxmox.com> 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 <!nocheck>,
+ rustc:native <!nocheck>,
+ libstd-rust-dev <!nocheck>,
+ librust-anyhow-1+default-dev <!nocheck>,
+ librust-log-0.4+default-dev (>= 0.4.17-~~) <!nocheck>,
+ librust-nix-0.26+default-dev (>= 0.26.1-~~) <!nocheck>,
+ librust-proxmox-sys-0.5+default-dev <!nocheck>,
+ librust-proxmox-time-1+default-dev (>= 1.1.4-~~) <!nocheck>,
+ librust-syslog-6+default-dev <!nocheck>,
+ librust-tokio-1+default-dev (>= 1.6-~~) <!nocheck>,
+ librust-tokio-1+rt-multi-thread-dev (>= 1.6-~~) <!nocheck>,
+ librust-tracing-0.1+default-dev <!nocheck>,
+ librust-tracing-log-0.1-dev (>= 0.1.3-~~) <!nocheck>,
+ librust-tracing-subscriber-0.3+default-dev (>= 0.3.16-~~) <!nocheck>
+Maintainer: Proxmox Support Team <support at proxmox.com>
+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 <support at proxmox.com>
+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 <https://www.gnu.org/licenses/>.
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 <support at proxmox.com>"
+
+[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<S: Subscriber> Layer<S> 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| {
+ log_to_file(&mut logger.borrow_mut(), event.metadata().level(), buf);
+ });
+ 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| 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<Mutex<bool>>,
+}
+
+impl WorkerTaskFilter {
+ pub fn new(in_worker_task: Arc<Mutex<bool>>) -> WorkerTaskFilter {
+ WorkerTaskFilter { in_worker_task }
+ }
+}
+
+impl<S: Subscriber + for<'a> LookupSpan<'a>> Filter<S> 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" {
+ 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<FileLogger>;
+ pub static WARN_COUNTER: RefCell<u64>;
+}
+
+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::<LevelFilter>() {
+ 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<Mutex<Logger<LoggerBackend, Formatter3164>>>,
+}
+
+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<S: Subscriber> Layer<S> 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));
+ }
+ }
+}
+
+pub struct InvertedWorkerTaskFilter {
+ in_worker_task: Arc<Mutex<bool>>,
+}
+
+impl InvertedWorkerTaskFilter {
+ pub fn new(in_worker_task: Arc<Mutex<bool>>) -> InvertedWorkerTaskFilter {
+ InvertedWorkerTaskFilter { in_worker_task }
+ }
+}
+
+impl<S: Subscriber + for<'lookup> LookupSpan<'lookup>> Filter<S> 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<oneshot::Sender<()>>,
}
@@ -808,7 +816,7 @@ impl WorkerTask {
worker_id: Option<String>,
auth_id: String,
to_stdout: bool,
- ) -> Result<Arc<Self>, Error> {
+ ) -> Result<(Arc<Self>, 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<WorkerTask>) -> T,
T: Send + 'static + Future<Output = 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 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)
+ .await;
});
Ok(upid_str)
@@ -895,22 +917,32 @@ impl WorkerTask {
where
F: Send + UnwindSafe + 'static + FnOnce(Arc<WorkerTask>) -> 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<S: AsRef<str>>(&self, msg: S) {
- let mut data = self.data.lock().unwrap();
- data.logger.log(msg);
- }
-
- /// Log a message as warning.
- pub fn log_warning<S: AsRef<str>>(&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<T: WorkerTaskContext + ?Sized> WorkerTaskContext for std::sync::Arc<T> {
fn fail_on_shutdown(&self) -> Result<(), Error> {
<T as WorkerTaskContext>::fail_on_shutdown(self)
}
-
- fn log(&self, level: log::Level, message: &std::fmt::Arguments) {
- <T as WorkerTaskContext>::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
More information about the pbs-devel
mailing list