public inbox for pbs-devel@lists.proxmox.com
 help / color / mirror / Atom feed
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
> 
> 




  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 a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox
Service provided by Proxmox Server Solutions GmbH | Privacy | Legal