From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from firstgate.proxmox.com (firstgate.proxmox.com [212.224.123.68]) by lore.proxmox.com (Postfix) with ESMTPS id BB9421FF2AA for ; Wed, 3 Jul 2024 16:05:33 +0200 (CEST) Received: from firstgate.proxmox.com (localhost [127.0.0.1]) by firstgate.proxmox.com (Proxmox) with ESMTP id 9267A994F; Wed, 3 Jul 2024 16:05:50 +0200 (CEST) Date: Wed, 3 Jul 2024 16:05:45 +0200 From: Wolfgang Bumiller To: Gabriel Goller Message-ID: References: <20240701092642.106030-1-g.goller@proxmox.com> <20240701092642.106030-2-g.goller@proxmox.com> MIME-Version: 1.0 Content-Disposition: inline In-Reply-To: <20240701092642.106030-2-g.goller@proxmox.com> X-SPAM-LEVEL: Spam detection results: 0 AWL 0.087 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, proxmox.com, options.read] Subject: Re: [pbs-devel] [PATCH proxmox v7 1/4] proxmox-log: add tracing infrastructure 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: , Reply-To: Proxmox Backup Server development discussion Cc: Lukas Wagner , pbs-devel@lists.proxmox.com Content-Type: text/plain; charset="us-ascii" Content-Transfer-Encoding: 7bit Errors-To: pbs-devel-bounces@lists.proxmox.com Sender: "pbs-devel" 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 > Tested-by: Lukas Wagner > Signed-off-by: Gabriel Goller > --- > 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 " > + > +[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>( > + file_name: P, > + options: FileLogOptions, > + ) -> Result { > + 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>( > + file_name: P, > + options: &FileLogOptions, > + ) -> Result { > + 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>(&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 { > + 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; > + pub static WARN_COUNTER: Cell; > +} > + > +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( > + 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 Layer 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