Re: [pbs-devel] [PATCH proxmox v5 1/4] proxmox-log: add tracing infrastructure

[Lukas Wagner <l.wagner@proxmox.com>]

Some comments inline

On  2024-06-13 15:56, Gabriel Goller wrote:
> Add the `proxmox_log` crate which includes the new logging infra.
> Export the `init_logger` function, which creates the `tracing` logger
> that includes the default subscriber and a single custom layer.
> 
> This layer checks on every event/log if a FileLogger is set in the
> task-local-storage, if it is, then log to the specified file, otherwise
> to syslog.
> 
> 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              |  52 +++++++++
>  proxmox-log/debian/copyright            |  18 +++
>  proxmox-log/debian/debcargo.toml        |   7 ++
>  proxmox-log/src/file_logger.rs          | 147 ++++++++++++++++++++++++
>  proxmox-log/src/lib.rs                  |  37 ++++++
>  proxmox-log/src/syslog_tasklog_layer.rs | 106 +++++++++++++++++
>  proxmox-rest-server/Cargo.toml          |   2 +
>  10 files changed, 403 insertions(+)
>  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_logger.rs
>  create mode 100644 proxmox-log/src/lib.rs
>  create mode 100644 proxmox-log/src/syslog_tasklog_layer.rs
> 
> diff --git a/Cargo.toml b/Cargo.toml
> index b3c97808..6e7bdb8d 100644
> --- a/Cargo.toml
> +++ b/Cargo.toml
> @@ -17,6 +17,7 @@ members = [
>      "proxmox-io",
>      "proxmox-lang",
>      "proxmox-ldap",
> +    "proxmox-log",
>      "proxmox-login",
>      "proxmox-metrics",
>      "proxmox-network-api",
> @@ -97,11 +98,15 @@ serde_cbor = "0.11.1"
>  serde_json = "1.0"
>  serde_plain = "1.0"
>  syn = { version = "2", features = [ "full", "visit-mut" ] }
> +syslog = "6"
>  tar = "0.4"
>  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"
> @@ -117,6 +122,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-product-config = { version = "0.1.0", path = "proxmox-product-config" }
>  proxmox-config-digest = { version = "0.1.0", path = "proxmox-config-digest" }
> diff --git a/proxmox-log/Cargo.toml b/proxmox-log/Cargo.toml
> new file mode 100644
> index 00000000..14ca6c7b
> --- /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

Just wondering, have you seen/checked out tracing-journald?
Would that be interesting for us?

https://docs.rs/tracing-journald/latest/tracing_journald/

> +nix.workspace = true
> +log.workspace = true
> +tracing.workspace = true
> +tracing-subscriber.workspace = true
> +tracing-log = { workspace = true, features = ["std"] }
> +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 00000000..3661bae9
> --- /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 00000000..14b2376d
> --- /dev/null
> +++ b/proxmox-log/debian/control
> @@ -0,0 +1,52 @@
> +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 (>= 0.5.1-~~) <!nocheck>,
> + librust-proxmox-time-1+default-dev (>= 1.1.6-~~) <!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.2
> +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 (>= 0.5.1-~~),
> + librust-proxmox-time-1+default-dev (>= 1.1.6-~~),
> + 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
> + Source code for Debianized Rust crate "proxmox-log"
> diff --git a/proxmox-log/debian/copyright b/proxmox-log/debian/copyright
> new file mode 100644
> index 00000000..b227c290
> --- /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 - 2024 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 00000000..b7864cdb
> --- /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_logger.rs b/proxmox-log/src/file_logger.rs
> new file mode 100644
> index 00000000..c7e1d644
> --- /dev/null
> +++ b/proxmox-log/src/file_logger.rs
> @@ -0,0 +1,147 @@
> +use std::io::Write;
> +
> +use anyhow::Error;
> +use nix::fcntl::OFlag;
> +
> +use proxmox_sys::fs::{atomic_open_or_create_file, CreateOptions};
> +
> +/// Options to control the behavior of a [FileLogger] instance
> +#[derive(Default)]
> +pub struct FileLogOptions {
> +    /// Open underlying log file in append mode, useful when multiple concurrent processes
> +    /// want to log to the same file (e.g., HTTP access log). Note that it is only atomic
> +    /// for writes smaller than the PIPE_BUF (4k on Linux).
> +    /// Inside the same process you may need to still use an mutex, for shared access.
> +    pub append: bool,
> +    /// Open underlying log file as readable
> +    pub read: bool,
> +    /// If set, ensure that the file is newly created or error out if already existing.
> +    pub exclusive: bool,
> +    /// Duplicate logged messages to STDOUT, like tee
> +    pub to_stdout: bool,
> +    /// Prefix messages logged to the file with the current local time as RFC 3339
> +    pub prefix_time: bool,
> +    /// File owner/group and mode
> +    pub file_opts: CreateOptions,
> +}
> +
> +/// Log messages with optional automatically added timestamps into files
> +///
> +/// #### Example:
> +/// ```
> +/// # use anyhow::{bail, format_err, Error};
> +/// use proxmox_log::{flog, FileLogger, FileLogOptions};
> +///
> +/// # std::fs::remove_file("test.log");
> +/// let options = FileLogOptions {
> +///     to_stdout: true,
> +///     exclusive: true,
> +///     ..Default::default()
> +/// };
> +/// let mut log = FileLogger::new("test.log", options).unwrap();
> +/// flog!(log, "A simple log: {}", "Hello!");
> +/// # std::fs::remove_file("test.log");
> +/// ```
> +pub struct FileLogger {
> +    file: std::fs::File,
> +    file_name: std::path::PathBuf,
> +    options: FileLogOptions,
> +}
> +
> +/// Log messages to [FileLogger] - ``println`` like macro
> +#[macro_export]
> +macro_rules! flog {
> +    ($log:expr, $($arg:tt)*) => ({
> +        $log.log(format!($($arg)*));
> +    })
> +}
> +
> +impl FileLogger {
> +    pub fn new<P: AsRef<std::path::Path>>(

Maybe add some doc comment for pub fn's?

> +        file_name: P,
> +        options: FileLogOptions,
> +    ) -> Result<Self, Error> {
> +        let file = Self::open(&file_name, &options)?;
> +
> +        let file_name: std::path::PathBuf = file_name.as_ref().to_path_buf();
> +
> +        Ok(Self {
> +            file,
> +            file_name,
> +            options,
> +        })
> +    }
> +
> +    pub fn reopen(&mut self) -> Result<&Self, Error> {

Maybe add some doc comment for pub fn's?

> +        let file = Self::open(&self.file_name, &self.options)?;
> +        self.file = file;
> +        Ok(self)
> +    }
> +
> +    fn open<P: AsRef<std::path::Path>>(
> +        file_name: P,
> +        options: &FileLogOptions,
> +    ) -> Result<std::fs::File, Error> {
> +        let mut flags = OFlag::O_CLOEXEC;
> +
> +        if options.read {
> +            flags |= OFlag::O_RDWR;
> +        } else {
> +            flags |= OFlag::O_WRONLY;
> +        }
> +
> +        if options.append {
> +            flags |= OFlag::O_APPEND;
> +        }
> +        if options.exclusive {
> +            flags |= OFlag::O_EXCL;
> +        }
> +
> +        let file =
> +            atomic_open_or_create_file(&file_name, flags, &[], options.file_opts.clone(), false)?;
> +
> +        Ok(file)
> +    }
> +
> +    pub fn log<S: AsRef<str>>(&mut self, msg: S) {

Maybe add some doc comment for pub fn's?

> +        let msg = msg.as_ref();
> +
> +        if self.options.to_stdout {
> +            let mut stdout = std::io::stdout();
> +            stdout.write_all(msg.as_bytes()).unwrap();
> +            stdout.write_all(b"\n").unwrap();

Instead of .unwrap'ing, you could just ignore the result:
  let _ = stdout.write_all(...);

If your 1000% sure that the write cannot fail, I'd like to see a comment
explaining why that is. Sometimes I also like to put that reasoning in the
message of .expect(...) and use that instead of .unwrap()

> +        }
> +
> +        let line = if self.options.prefix_time {
> +            let now = proxmox_time::epoch_i64();
> +            let rfc3339 = match proxmox_time::epoch_to_rfc3339(now) {
> +                Ok(rfc3339) => rfc3339,
> +                Err(_) => "1970-01-01T00:00:00Z".into(), // for safety, should really not happen!
> +            };
> +            format!("{}: {}\n", rfc3339, msg)
> +        } else {
> +            format!("{}\n", msg)

You could inline these vars in the format string

> +        };
> +        if let Err(err) = self.file.write_all(line.as_bytes()) {
> +            // avoid panicking, log methods should not do that
> +            // FIXME: or, return result???
> +            log::error!("error writing to log file - {}", err);

Since you use `FileLogger` in `SyslogAndTaskLogger` as a tracing logging layer and
also setup the `tracing-log` bridge to convert log records to tracing events,
wouldn't this lead to recursion?

> +        }
> +    }
> +}
> +
> +impl std::io::Write for FileLogger {
> +    fn write(&mut self, buf: &[u8]) -> Result<usize, std::io::Error> {
> +        if self.options.to_stdout {
> +            let _ = std::io::stdout().write(buf);
> +        }
> +        self.file.write(buf)
> +    }
> +
> +    fn flush(&mut self) -> Result<(), std::io::Error> {
> +        if self.options.to_stdout {
> +            let _ = std::io::stdout().flush();
> +        }
> +        self.file.flush()
> +    }
> +}
> diff --git a/proxmox-log/src/lib.rs b/proxmox-log/src/lib.rs
> new file mode 100644
> index 00000000..daaaede5
> --- /dev/null
> +++ b/proxmox-log/src/lib.rs
> @@ -0,0 +1,37 @@
> +use std::{
> +    cell::{Cell, RefCell},
> +    env,
> +};
> +use syslog_tasklog_layer::SyslogAndTasklogLayer;
> +use tracing_log::{AsLog, LogTracer};
> +use tracing_subscriber::filter::LevelFilter;
> +use tracing_subscriber::prelude::*;
> +
> +mod file_logger;
> +pub use file_logger::{FileLogOptions, FileLogger};
> +
> +mod syslog_tasklog_layer;
> +
> +tokio::task_local! {
> +    pub static LOGGER: RefCell<FileLogger>;
> +    pub static WARN_COUNTER: Cell<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 registry = tracing_subscriber::registry()
> +        .with(SyslogAndTasklogLayer::new(application_name.to_string()).with_filter(log_level));
> +
> +    tracing::subscriber::set_global_default(registry)?;
> +    LogTracer::init_with_filter(log_level.as_log())?;
> +    Ok(())
> +}
> diff --git a/proxmox-log/src/syslog_tasklog_layer.rs b/proxmox-log/src/syslog_tasklog_layer.rs
> new file mode 100644
> index 00000000..89437caf
> --- /dev/null
> +++ b/proxmox-log/src/syslog_tasklog_layer.rs
> @@ -0,0 +1,106 @@
> +use std::fmt::Write as _;
> +use std::sync::Arc;
> +use std::sync::Mutex;
> +
> +use syslog::{Formatter3164, LoggerBackend};
> +use tracing::field::Field;
> +use tracing::field::Visit;
> +use tracing::Event;
> +use tracing::Level;
> +use tracing::Subscriber;
> +use tracing_subscriber::layer::Context;
> +use tracing_subscriber::Layer;
> +
> +use crate::FileLogger;
> +use crate::LOGGER;
> +use crate::WARN_COUNTER;
> +
> +pub struct SyslogAndTasklogLayer {
> +    syslog_logger: Arc<Mutex<syslog::Logger<LoggerBackend, Formatter3164>>>,
> +}
> +
> +impl SyslogAndTasklogLayer {
> +    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)

Maybe explain why it is okay to panic in this case? (is it?)

> +            .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 {
> +            syslog_logger: logger,
> +        }
> +    }
> +}
> +
> +impl<S: Subscriber> Layer<S> for SyslogAndTasklogLayer {
> +    fn on_event(&self, event: &Event<'_>, _ctx: Context<'_, S>) {
> +        let mut buf = String::new();
> +        event.record(&mut EventVisitor::new(&mut buf));
> +        let level = event.metadata().level();
> +
> +        let result = LOGGER.try_with(|logger| {
> +            log_to_file(&mut logger.borrow_mut(), level, &buf);
> +        });
> +        if result.is_err() || *level == Level::ERROR {
> +            log_to_syslog(&mut self.syslog_logger.lock().unwrap(), level, &buf);

Also could do the .expect with an explanatory message here

> +        }
> +    }
> +}
> +
> +fn log_to_syslog(
> +    logger: &mut syslog::Logger<LoggerBackend, Formatter3164>,
> +    level: &Level,
> +    buf: &String,
> +) {
> +    let _ = match *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),
> +    };
> +}
> +fn log_to_file(logger: &mut FileLogger, level: &Level, buf: &String) {
> +    match *level {
> +        Level::ERROR | Level::WARN => {
> +            WARN_COUNTER.with(|counter| {
> +                counter.set(counter.get() + 1);
> +            });
> +            logger.log(buf);
> +        }
> +        Level::INFO => logger.log(buf),
> +        Level::DEBUG => logger.log(format!("DEBUG: {}", buf)),
> +        Level::TRACE => logger.log(format!("TRACE: {}", buf)),

You could inline these vars :)

> +    };
> +}
> +
> +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" {
> +            let _ = write!(self.buf, "{value:?}");
> +        }
> +    }
> +}
> diff --git a/proxmox-rest-server/Cargo.toml b/proxmox-rest-server/Cargo.toml
> index 94330ff1..2bfea4a0 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

please keep the alphabetic order :)

>  
>  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

Same here

>  
>  [features]
>  default = []

-- 
- Lukas


_______________________________________________
pbs-devel mailing list
pbs-devel@lists.proxmox.com
https://lists.proxmox.com/cgi-bin/mailman/listinfo/pbs-devel