[pbs-devel] [RFC proxmox 2/2] proxmox-log: added tracing infra

[Gabriel Goller]

Thanks for the review (comments inline).

On 10/18/23 15:26, Dominik Csapak wrote:
> i just glanced over the code but a few comments inline
>
> On 10/11/23 16:01, Gabriel Goller wrote:
> [..snip..]
>> diff --git a/proxmox-log/src/file_layer.rs 
>> b/proxmox-log/src/file_layer.rs
>> new file mode 100644
>> index 0000000..1a167f4
>> --- /dev/null
>> +++ b/proxmox-log/src/file_layer.rs
>> @@ -0,0 +1,89 @@
>> +use std::cell::RefCell;
>> +use tracing::error;
>> +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;
>> +
>> +tokio::task_local! {
>> +    pub static LOGGER: RefCell<Option<FileLogger>>;
>> +    pub static WARN_COUNTER: RefCell<Option<u64>>;
>
> why are these wrapped in options? with 'try_with' you get an error
> anyway when they don't exists and i did not see a place
> where you'd set them to None?
Right, this was a relic from when I used `thread_local`, now with
`task_local` its not used anymore. Thanks!
>
>> +}
>> +
>> +pub struct FilelogLayer {}
>> +
>> +impl FilelogLayer {
>> +    pub fn new() -> Self {
>> +        Self {}
>> +    }
>> +}
>> +
>> +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));
>> +
>> +        let logger_exists = LOGGER.try_with(|logger| {
>> +            let mut l = logger.borrow_mut();
>> +            let log = l.as_mut();
>> +            if let Some(l) = log {
>> +                log_to_file(l, event.metadata().level(), buf);
>> +            } else {
>> +                error!("FileLogger not found");
>> +            }
>> +        });
>> +        if let Err(e) = logger_exists {
>> +            error!(
>> +                "Error getting the logger from the task-local 
>> storage: {}",
>> +                e
>> +            )
>> +        }
>
> this would be much shorter if it wasn't for the Option<>
>
>> +    }
>> +}
>> +
>> +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| {
>> +                    if let Some(v) = c {
>> +                        Some(v.to_owned() + 1)
>> +                    } else {
>> +                        None
>> +                    }
>> +                });
>
> two things here:
> * do we really want to increase the warn counter for error too?
>   (i can't remember what we do now)
>   normally we abort on an error anyway, so that does not make sense
>   or if we now can log an error without aborting, we'd probably want
>   to have a separate error count?
We always incremented the `warn_counter` on error and warning. The thing is
we don't really use it when there is an error (check `create_state()` in 
worker_task.rs).
I don't have any strong feelings on this, we could also leave it as it 
is, as one could
interpret it as 'counter of events of level warn and higher'.
>
> * clippy says this is a manually implemented map:
>
> counter.replace_with(|c| c.as_mut().map(|v| v.to_owned() + 1));
>
not necessary anymore, as I removed the Option<> wrap.
>
>
>> +                logger.log(buf.clone());
>> +            });
>> +            if let Err(e) = counter_exists {
>> +                error!("Error getting the warning_counter for the 
>> logger: {}", e)
>> +            }
>> +        }
>> +        &Level::INFO => logger.log(buf.clone()),
>
> this clone is redundant (thanks clippy ;) )
Fixed this and some other clippy lints :)
>
>> +        &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));
>> +        }
>> +    }
>> +}
>> 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..0c101b7
>> --- /dev/null
>> +++ b/proxmox-log/src/lib.rs
>> @@ -0,0 +1,36 @@
>> +//! # Proxmox logging infrastructure
>> +use crate::syslog_layer::SyslogLayer;
>> +use file_layer::FilelogLayer;
>> +use std::env;
>> +use tracing_log::LogTracer;
>> +use tracing_subscriber::filter::{filter_fn, LevelFilter};
>> +use tracing_subscriber::prelude::*;
>> +
>> +pub mod file_layer;
>> +mod file_logger;
>> +pub use file_logger::{FileLogOptions, FileLogger};
>> +
>> +mod syslog_layer;
>> +
>> +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(FilelogLayer::new().with_filter(filter_fn(|metadata| {
>> +            metadata.fields().field("tasklog").is_some()
>
> you give 'tasklog = true' but only check here for is_some, wouldn't
> it be better to do
> metadata.fields().field("tasklog") == Some("true")
> ?
> that way a
> 'tasklog = false' wouldn't (confusingly) log to the task log
>
Sadly, we can't do that, because tracing only records the field names
before enabling/disabling a layer (because of performance reasons,
computing the value **could** be expensive).
> [..]
>