From: Wolfgang Bumiller <w.bumiller@proxmox.com>
To: Gabriel Goller <g.goller@proxmox.com>
Cc: pbs-devel@lists.proxmox.com
Subject: Re: [pbs-devel] [RFC proxmox v2 2/2] proxmox-log: added tracing infra
Date: Thu, 2 Nov 2023 14:43:50 +0100 [thread overview]
Message-ID: <uilsuhdampqxjkl6j4iqdwnsto2ntft2v2774h7xhulcgaq6lh@knus6hopuhyy> (raw)
In-Reply-To: <20231025135325.198073-3-g.goller@proxmox.com>
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 <g.goller@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@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@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@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@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));
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<Mutex<bool>>,
AFAICT you only have locks which are shortlived to set/clear/check this
value.
For such a thing you can use `Arc<AtomicBool>` and get rid of all the
error handling.
> +}
> +
> +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" {
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<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));
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<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)
^ 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<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
>
>
>
> _______________________________________________
> pbs-devel mailing list
> pbs-devel@lists.proxmox.com
> https://lists.proxmox.com/cgi-bin/mailman/listinfo/pbs-devel
>
>
next prev parent reply other threads:[~2023-11-02 13:43 UTC|newest]
Thread overview: 12+ messages / expand[flat|nested] mbox.gz Atom feed top
2023-10-25 13:53 [pbs-devel] [RFC proxmox-backup v2 0/2] Tasklog rewrite with tracing Gabriel Goller
2023-10-25 13:53 ` [pbs-devel] [RFC proxmox-backup v2 1/2] log: removed task_log! macro and moved to tracing Gabriel Goller
2023-10-27 8:31 ` Gabriel Goller
2023-10-25 13:53 ` [pbs-devel] [RFC proxmox v2 2/2] proxmox-log: added tracing infra Gabriel Goller
2023-11-02 13:43 ` Wolfgang Bumiller [this message]
2023-11-02 14:58 ` Gabriel Goller
2023-11-03 8:56 ` Wolfgang Bumiller
2023-11-03 9:24 ` Gabriel Goller
2023-11-03 9:52 ` Wolfgang Bumiller
2023-11-03 10:27 ` Gabriel Goller
2023-11-03 10:39 ` Wolfgang Bumiller
2023-11-03 10:49 ` Gabriel Goller
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=uilsuhdampqxjkl6j4iqdwnsto2ntft2v2774h7xhulcgaq6lh@knus6hopuhyy \
--to=w.bumiller@proxmox.com \
--cc=g.goller@proxmox.com \
--cc=pbs-devel@lists.proxmox.com \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.