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

[Gabriel Goller]

On 03.07.2024 16:05, Wolfgang Bumiller wrote:
>On Mon, Jul 01, 2024 at 11:26:30AM GMT, Gabriel Goller wrote:
>> diff --git a/proxmox-log/src/file_logger.rs b/proxmox-log/src/file_logger.rs
>> +/// 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.

I agree, removed it and adjusted the comment above.

>> +    ($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.

Oops, yeah this is my bad. It somehow sneaked in again in the last
version :(

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

I removed it from the task-log layer and did some quick benchmarking:

     Benchmark 1: ./target/debug/slow
       Time (mean ± σ):      30.9 ms ±   4.9 ms    [User: 22.1 ms, System: 8.3 ms]
       Range (min … max):    27.6 ms …  74.6 ms    10000 runs

     Benchmark 2: ./target/debug/rust_test
       Time (mean ± σ):      26.7 ms ±   4.5 ms    [User: 18.6 ms, System: 7.6 ms]
       Range (min … max):    24.0 ms …  82.9 ms    10000 runs

     Summary
       './target/debug/rust_test' ran
         1.16 ± 0.27 times faster than './target/debug/slow'

Note the last line—without the LOGGER check in the filter_fn we are
1.16 times faster!

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

Done. Thanks for the review!