From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from firstgate.proxmox.com (firstgate.proxmox.com [212.224.123.68]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (2048 bits) server-digest SHA256) (No client certificate requested) by lists.proxmox.com (Postfix) with ESMTPS id 82D7A9C031 for ; Mon, 23 Oct 2023 10:56:59 +0200 (CEST) Received: from firstgate.proxmox.com (localhost [127.0.0.1]) by firstgate.proxmox.com (Proxmox) with ESMTP id 604BA10FB1 for ; Mon, 23 Oct 2023 10:56:29 +0200 (CEST) Received: from proxmox-new.maurer-it.com (proxmox-new.maurer-it.com [94.136.29.106]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (2048 bits) server-digest SHA256) (No client certificate requested) by firstgate.proxmox.com (Proxmox) with ESMTPS for ; Mon, 23 Oct 2023 10:56:28 +0200 (CEST) Received: from proxmox-new.maurer-it.com (localhost.localdomain [127.0.0.1]) by proxmox-new.maurer-it.com (Proxmox) with ESMTP id 626A344200 for ; Mon, 23 Oct 2023 10:56:28 +0200 (CEST) Message-ID: <8ff66ba9-9b5f-444e-a380-98797ca5ba5b@proxmox.com> Date: Mon, 23 Oct 2023 10:56:27 +0200 MIME-Version: 1.0 User-Agent: Mozilla Thunderbird Content-Language: en-US To: Dominik Csapak , Proxmox Backup Server development discussion References: <20231011140102.273423-1-g.goller@proxmox.com> <20231011140102.273423-3-g.goller@proxmox.com> From: Gabriel Goller In-Reply-To: Content-Type: text/plain; charset=UTF-8; format=flowed Content-Transfer-Encoding: 8bit X-SPAM-LEVEL: Spam detection results: 0 AWL -0.305 Adjusted score from AWL reputation of From: address BAYES_00 -1.9 Bayes spam probability is 0 to 1% DMARC_MISSING 0.1 Missing DMARC policy KAM_DMARC_STATUS 0.01 Test Rule for DKIM or SPF Failure with Strict Alignment SPF_HELO_NONE 0.001 SPF: HELO does not publish an SPF Record SPF_PASS -0.001 SPF: sender matches SPF record URIBL_BLOCKED 0.001 ADMINISTRATOR NOTICE: The query to URIBL was blocked. See http://wiki.apache.org/spamassassin/DnsBlocklists#dnsbl-block for more information. [lib.rs] Subject: Re: [pbs-devel] [RFC proxmox 2/2] proxmox-log: added tracing infra X-BeenThere: pbs-devel@lists.proxmox.com X-Mailman-Version: 2.1.29 Precedence: list List-Id: Proxmox Backup Server development discussion List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Mon, 23 Oct 2023 08:56:59 -0000 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>; >> +    pub static WARN_COUNTER: RefCell>; > > 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 Layer 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::() { >> +            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). > [..] >