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

[Wolfgang Bumiller <w.bumiller@proxmox.com>]

On Mon, Jul 01, 2024 at 11:26:30AM GMT, 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 two layer.
> 
> The first layer comes from the tracing-journald crate and logs
> everything that does not come from a worker-task/thread to the syslog.
> The second layer filters the exact opposite and writes the logs into the
> corresponding task-log file.
> 
> Reviewed-by: Lukas Wagner <l.wagner@proxmox.com>
> Tested-by: Lukas Wagner <l.wagner@proxmox.com>
> Signed-off-by: Gabriel Goller <g.goller@proxmox.com>
> ---
> diff --git a/proxmox-log/debian/debcargo.toml b/proxmox-log/debian/debcargo.toml
> new file mode 100644
> index 000000000000..b7864cdbab7d
> --- /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 000000000000..1f58d8979a3a
> --- /dev/null
> +++ b/proxmox-log/src/file_logger.rs
> @@ -0,0 +1,151 @@
> +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 {

AFAICT this is completely unused and I don't think we'll actually be
using FileLogger like this anyway, so I'd say we can drop this.

> +    ($log:expr, $($arg:tt)*) => ({
> +        $log.log(format!($($arg)*));
> +    })
> +}
> +
> +impl FileLogger {
> +    /// Create a new FileLogger. This opens the specified file and
> +    /// stores a file descriptor.
> +    pub fn new<P: AsRef<std::path::Path>>(
> +        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,
> +        })
> +    }
> +
> +    /// Reopen logfile.
> +    pub fn reopen(&mut self) -> Result<&Self, Error> {
> +        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)
> +    }
> +
> +    /// Writes `msg` to the logfile with a timestamp and to stdout if
> +    /// specified.
> +    pub fn log<S: AsRef<str>>(&mut self, msg: S) {
> +        let msg = msg.as_ref();
> +
> +        if self.options.to_stdout {
> +            let mut stdout = std::io::stdout();
> +            let _ = stdout.write_all(msg.as_bytes());
> +            let _ = stdout.write_all(b"\n");
> +        }
> +
> +        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!("{rfc3339}: {msg}\n")
> +        } else {
> +            format!("{msg}\n")
> +        };
> +        // Note: we ignore the potential error here because log methods
> +        // shouldn't panic. We also can't log an error, because that
> +        // would lead to recursion.
> +        let _ = self.file.write_all(line.as_bytes());
> +    }
> +}
> +
> +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 000000000000..5fd7ac1c4636
> --- /dev/null
> +++ b/proxmox-log/src/lib.rs
> @@ -0,0 +1,52 @@
> +use std::{
> +    cell::{Cell, RefCell},
> +    env,
> +};
> +
> +use tracing::Level;
> +use tracing_log::{AsLog, LogTracer};
> +use tracing_subscriber::filter::{filter_fn, LevelFilter};
> +use tracing_subscriber::prelude::*;
> +
> +use tasklog_layer::TasklogLayer;
> +
> +mod file_logger;
> +pub use file_logger::{FileLogOptions, FileLogger};
> +
> +mod 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(
> +            tracing_journald::layer()
> +                .expect("Unable to open syslog")
> +                .with_filter(log_level)
> +                .with_filter(filter_fn(|metadata| {
> +                    LOGGER.try_with(|_| {}).is_err() || *metadata.level() == Level::ERROR
> +                })),
> +        )
> +        .with(
> +            TasklogLayer {}
> +                .with_filter(log_level)
> +                .with_filter(filter_fn(|_| LOGGER.try_with(|_| {}).is_ok())),
> +        );
> +
> +    tracing::subscriber::set_global_default(registry)?;
> +    LogTracer::init_with_filter(log_level.as_log())?;
> +    Ok(())
> +}
> diff --git a/proxmox-log/src/tasklog_layer.rs b/proxmox-log/src/tasklog_layer.rs
> new file mode 100644
> index 000000000000..e25ded8cbcd4
> --- /dev/null
> +++ b/proxmox-log/src/tasklog_layer.rs
> @@ -0,0 +1,59 @@
> +use std::fmt::Write as _;
> +
> +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 TasklogLayer;
> +
> +impl<S: Subscriber> Layer<S> for TasklogLayer {
> +    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();

I actually mentioned this in a very early version: The string should be
built within the try_with closure below, since if we don't have a
LOGGER we'll only be throwing it away.

This does also make me wonder if we really need the filter on the layer
to test whether LOGGER is usable... not sure how efficient the
implementation is on the tracing crate side if the on_event method is
entered.

> +
> +        let _result = LOGGER.try_with(|logger| {
> +            log_to_file(&mut logger.borrow_mut(), level, &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}")),
> +    };
> +}
> +
> +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 5ffde0d6f210..20f43a69a4d0 100644
> --- a/proxmox-rest-server/Cargo.toml
> +++ b/proxmox-rest-server/Cargo.toml

This hunk should be in the 2nd patch.

> @@ -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 = []
> -- 
> 2.43.0


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