From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from ronja.mits.lan by ronja.mits.lan with LMTP id EEgOHCJUeWbWZQAAxxbTJA (envelope-from ); Mon, 24 Jun 2024 13:10:26 +0200 Received: from proxmox-new.maurer-it.com (unknown [192.168.2.33]) by ronja.mits.lan (Postfix) with ESMTPS id 57D63F6462A; Mon, 24 Jun 2024 13:10:26 +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 3DB984858D; Mon, 24 Jun 2024 13:10:26 +0200 (CEST) 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 (4096 bits)) (No client certificate requested) by proxmox-new.maurer-it.com (Proxmox) with ESMTPS; Mon, 24 Jun 2024 13:10:23 +0200 (CEST) Received: from firstgate.proxmox.com (localhost [127.0.0.1]) by firstgate.proxmox.com (Proxmox) with ESMTP id 759AD34E09; Mon, 24 Jun 2024 13:10:23 +0200 (CEST) Message-ID: Date: Mon, 24 Jun 2024 13:10:17 +0200 MIME-Version: 1.0 User-Agent: Mozilla Thunderbird From: Lukas Wagner To: Proxmox Backup Server development discussion , Gabriel Goller References: <20240613135623.279167-1-g.goller@proxmox.com> <20240613135623.279167-2-g.goller@proxmox.com> Content-Language: de-AT, en-US In-Reply-To: <20240613135623.279167-2-g.goller@proxmox.com> Subject: Re: [pbs-devel] [PATCH proxmox v5 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 Content-Type: text/plain; charset="us-ascii" Content-Transfer-Encoding: 7bit Errors-To: pbs-devel-bounces@lists.proxmox.com Sender: "pbs-devel" X-SPAM-LEVEL: Spam detection results: 0 DMARC_MISSING 0.1 Missing DMARC policy KAM_DMARC_STATUS 0.01 Test Rule for DKIM or SPF Failure with Strict Alignment KAM_LAZY_DOMAIN_SECURITY 1 Sending domain does not have any anti-forgery methods MAILING_LIST_MULTI -2 Multiple indicators imply a widely-seen list manager RCVD_IN_DNSWL_MED -2.3 Sender listed at https://www.dnswl.org/, medium trust SPF_HELO_NONE 0.001 SPF: HELO does not publish an SPF Record SPF_NONE 0.001 SPF: sender does not publish an SPF Record Some comments inline On 2024-06-13 15:56, 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 a single custom layer. > > This layer checks on every event/log if a FileLogger is set in the > task-local-storage, if it is, then log to the specified file, otherwise > to syslog. > > Signed-off-by: Gabriel Goller > --- > Cargo.toml | 6 + > proxmox-log/Cargo.toml | 23 ++++ > proxmox-log/debian/changelog | 5 + > proxmox-log/debian/control | 52 +++++++++ > proxmox-log/debian/copyright | 18 +++ > proxmox-log/debian/debcargo.toml | 7 ++ > proxmox-log/src/file_logger.rs | 147 ++++++++++++++++++++++++ > proxmox-log/src/lib.rs | 37 ++++++ > proxmox-log/src/syslog_tasklog_layer.rs | 106 +++++++++++++++++ > proxmox-rest-server/Cargo.toml | 2 + > 10 files changed, 403 insertions(+) > create mode 100644 proxmox-log/Cargo.toml > create mode 100644 proxmox-log/debian/changelog > create mode 100644 proxmox-log/debian/control > create mode 100644 proxmox-log/debian/copyright > create mode 100644 proxmox-log/debian/debcargo.toml > create mode 100644 proxmox-log/src/file_logger.rs > create mode 100644 proxmox-log/src/lib.rs > create mode 100644 proxmox-log/src/syslog_tasklog_layer.rs > > diff --git a/Cargo.toml b/Cargo.toml > index b3c97808..6e7bdb8d 100644 > --- a/Cargo.toml > +++ b/Cargo.toml > @@ -17,6 +17,7 @@ members = [ > "proxmox-io", > "proxmox-lang", > "proxmox-ldap", > + "proxmox-log", > "proxmox-login", > "proxmox-metrics", > "proxmox-network-api", > @@ -97,11 +98,15 @@ serde_cbor = "0.11.1" > serde_json = "1.0" > serde_plain = "1.0" > syn = { version = "2", features = [ "full", "visit-mut" ] } > +syslog = "6" > tar = "0.4" > tokio = "1.6" > tokio-openssl = "0.6.1" > tokio-stream = "0.1.0" > tower-service = "0.3.0" > +tracing = "0.1" > +tracing-log = { version = "0.1.3", default-features = false } > +tracing-subscriber = "0.3.16" > url = "2.2" > walkdir = "2" > webauthn-rs = "0.3" > @@ -117,6 +122,7 @@ proxmox-http-error = { version = "0.1.0", path = "proxmox-http-error" } > proxmox-human-byte = { version = "0.1.0", path = "proxmox-human-byte" } > proxmox-io = { version = "1.0.0", path = "proxmox-io" } > proxmox-lang = { version = "1.1", path = "proxmox-lang" } > +proxmox-log= { version = "0.1.0", path = "proxmox-log" } > proxmox-login = { version = "0.1.0", path = "proxmox-login" } > proxmox-product-config = { version = "0.1.0", path = "proxmox-product-config" } > proxmox-config-digest = { version = "0.1.0", path = "proxmox-config-digest" } > diff --git a/proxmox-log/Cargo.toml b/proxmox-log/Cargo.toml > new file mode 100644 > index 00000000..14ca6c7b > --- /dev/null > +++ b/proxmox-log/Cargo.toml > @@ -0,0 +1,23 @@ > +[package] > +name = "proxmox-log" > +version = "0.1.0" > +authors.workspace = true > +edition.workspace = true > +license.workspace = true > +repository.workspace = true > +description = "Logging infrastructure for proxmox" > + > +exclude.workspace = true > + > +[dependencies] > +anyhow.workspace = true > +syslog.workspace = true Just wondering, have you seen/checked out tracing-journald? Would that be interesting for us? https://docs.rs/tracing-journald/latest/tracing_journald/ > +nix.workspace = true > +log.workspace = true > +tracing.workspace = true > +tracing-subscriber.workspace = true > +tracing-log = { workspace = true, features = ["std"] } > +tokio = { workspace = true, features = ["rt-multi-thread"] } > +proxmox-time.workspace = true > +proxmox-sys.workspace = true > + > diff --git a/proxmox-log/debian/changelog b/proxmox-log/debian/changelog > new file mode 100644 > index 00000000..3661bae9 > --- /dev/null > +++ b/proxmox-log/debian/changelog > @@ -0,0 +1,5 @@ > +rust-proxmox-log (0.1.0-3) UNRELEASED; urgency=medium > + > + * Initial release > + > + -- Gabriel Goller Wed, 11 Oct 2023 15:13:58 +0200 > diff --git a/proxmox-log/debian/control b/proxmox-log/debian/control > new file mode 100644 > index 00000000..14b2376d > --- /dev/null > +++ b/proxmox-log/debian/control > @@ -0,0 +1,52 @@ > +Source: rust-proxmox-log > +Section: rust > +Priority: optional > +Build-Depends: debhelper (>= 12), > + dh-cargo (>= 25), > + cargo:native , > + rustc:native , > + libstd-rust-dev , > + librust-anyhow-1+default-dev , > + librust-log-0.4+default-dev (>= 0.4.17-~~) , > + librust-nix-0.26+default-dev (>= 0.26.1-~~) , > + librust-proxmox-sys-0.5+default-dev (>= 0.5.1-~~) , > + librust-proxmox-time-1+default-dev (>= 1.1.6-~~) , > + librust-syslog-6+default-dev , > + librust-tokio-1+default-dev (>= 1.6-~~) , > + librust-tokio-1+rt-multi-thread-dev (>= 1.6-~~) , > + librust-tracing-0.1+default-dev , > + librust-tracing-log-0.1-dev (>= 0.1.3-~~) , > + librust-tracing-subscriber-0.3+default-dev (>= 0.3.16-~~) > +Maintainer: Proxmox Support Team > +Standards-Version: 4.6.2 > +Vcs-Git: git://git.proxmox.com/git/proxmox.git > +Vcs-Browser: https://git.proxmox.com/?p=proxmox.git > +X-Cargo-Crate: proxmox-log > +Rules-Requires-Root: no > + > +Package: librust-proxmox-log-dev > +Architecture: any > +Multi-Arch: same > +Depends: > + ${misc:Depends}, > + librust-anyhow-1+default-dev, > + librust-log-0.4+default-dev (>= 0.4.17-~~), > + librust-nix-0.26+default-dev (>= 0.26.1-~~), > + librust-proxmox-sys-0.5+default-dev (>= 0.5.1-~~), > + librust-proxmox-time-1+default-dev (>= 1.1.6-~~), > + librust-syslog-6+default-dev, > + librust-tokio-1+default-dev (>= 1.6-~~), > + librust-tokio-1+rt-multi-thread-dev (>= 1.6-~~), > + librust-tracing-0.1+default-dev, > + librust-tracing-log-0.1-dev (>= 0.1.3-~~), > + librust-tracing-subscriber-0.3+default-dev (>= 0.3.16-~~) > +Provides: > + librust-proxmox-log+default-dev (= ${binary:Version}), > + librust-proxmox-log-0-dev (= ${binary:Version}), > + librust-proxmox-log-0+default-dev (= ${binary:Version}), > + librust-proxmox-log-0.1-dev (= ${binary:Version}), > + librust-proxmox-log-0.1+default-dev (= ${binary:Version}), > + librust-proxmox-log-0.1.0-dev (= ${binary:Version}), > + librust-proxmox-log-0.1.0+default-dev (= ${binary:Version}) > +Description: Logging infrastructure for proxmox - Rust source code > + Source code for Debianized Rust crate "proxmox-log" > diff --git a/proxmox-log/debian/copyright b/proxmox-log/debian/copyright > new file mode 100644 > index 00000000..b227c290 > --- /dev/null > +++ b/proxmox-log/debian/copyright > @@ -0,0 +1,18 @@ > +Format: https://www.debian.org/doc/packaging-manuals/copyright-format/1.0/ > + > +Files: > + * > +Copyright: 2019 - 2024 Proxmox Server Solutions GmbH > +License: AGPL-3.0-or-later > + This program is free software: you can redistribute it and/or modify it under > + the terms of the GNU Affero General Public License as published by the Free > + Software Foundation, either version 3 of the License, or (at your option) any > + later version. > + . > + This program is distributed in the hope that it will be useful, but WITHOUT > + ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or FITNESS > + FOR A PARTICULAR PURPOSE. See the GNU Affero General Public License for more > + details. > + . > + You should have received a copy of the GNU Affero General Public License along > + with this program. If not, see . > diff --git a/proxmox-log/debian/debcargo.toml b/proxmox-log/debian/debcargo.toml > new file mode 100644 > index 00000000..b7864cdb > --- /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 00000000..c7e1d644 > --- /dev/null > +++ b/proxmox-log/src/file_logger.rs > @@ -0,0 +1,147 @@ > +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 { > + ($log:expr, $($arg:tt)*) => ({ > + $log.log(format!($($arg)*)); > + }) > +} > + > +impl FileLogger { > + pub fn new>( Maybe add some doc comment for pub fn's? > + 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, > + }) > + } > + > + pub fn reopen(&mut self) -> Result<&Self, Error> { Maybe add some doc comment for pub fn's? > + 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) > + } > + > + pub fn log>(&mut self, msg: S) { Maybe add some doc comment for pub fn's? > + let msg = msg.as_ref(); > + > + if self.options.to_stdout { > + let mut stdout = std::io::stdout(); > + stdout.write_all(msg.as_bytes()).unwrap(); > + stdout.write_all(b"\n").unwrap(); Instead of .unwrap'ing, you could just ignore the result: let _ = stdout.write_all(...); If your 1000% sure that the write cannot fail, I'd like to see a comment explaining why that is. Sometimes I also like to put that reasoning in the message of .expect(...) and use that instead of .unwrap() > + } > + > + 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!("{}: {}\n", rfc3339, msg) > + } else { > + format!("{}\n", msg) You could inline these vars in the format string > + }; > + if let Err(err) = self.file.write_all(line.as_bytes()) { > + // avoid panicking, log methods should not do that > + // FIXME: or, return result??? > + log::error!("error writing to log file - {}", err); Since you use `FileLogger` in `SyslogAndTaskLogger` as a tracing logging layer and also setup the `tracing-log` bridge to convert log records to tracing events, wouldn't this lead to recursion? > + } > + } > +} > + > +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 00000000..daaaede5 > --- /dev/null > +++ b/proxmox-log/src/lib.rs > @@ -0,0 +1,37 @@ > +use std::{ > + cell::{Cell, RefCell}, > + env, > +}; > +use syslog_tasklog_layer::SyslogAndTasklogLayer; > +use tracing_log::{AsLog, LogTracer}; > +use tracing_subscriber::filter::LevelFilter; > +use tracing_subscriber::prelude::*; > + > +mod file_logger; > +pub use file_logger::{FileLogOptions, FileLogger}; > + > +mod syslog_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(SyslogAndTasklogLayer::new(application_name.to_string()).with_filter(log_level)); > + > + tracing::subscriber::set_global_default(registry)?; > + LogTracer::init_with_filter(log_level.as_log())?; > + Ok(()) > +} > diff --git a/proxmox-log/src/syslog_tasklog_layer.rs b/proxmox-log/src/syslog_tasklog_layer.rs > new file mode 100644 > index 00000000..89437caf > --- /dev/null > +++ b/proxmox-log/src/syslog_tasklog_layer.rs > @@ -0,0 +1,106 @@ > +use std::fmt::Write as _; > +use std::sync::Arc; > +use std::sync::Mutex; > + > +use syslog::{Formatter3164, LoggerBackend}; > +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 SyslogAndTasklogLayer { > + syslog_logger: Arc>>, > +} > + > +impl SyslogAndTasklogLayer { > + pub fn new(application_name: String) -> Self { > + let formatter = Formatter3164 { > + facility: syslog::Facility::LOG_DAEMON, > + process: application_name, > + ..Formatter3164::default() > + }; > + > + // we panic here if we can't initialize the syslogger > + let logger = syslog::unix(formatter) Maybe explain why it is okay to panic in this case? (is it?) > + .map_err(|e| { > + anyhow::Error::new(std::io::Error::new( > + std::io::ErrorKind::Other, > + e.description(), > + )) > + }) > + .unwrap(); > + > + let logger = Arc::new(Mutex::new(logger)); > + > + Self { > + syslog_logger: logger, > + } > + } > +} > + > +impl Layer for SyslogAndTasklogLayer { > + 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(); > + > + let result = LOGGER.try_with(|logger| { > + log_to_file(&mut logger.borrow_mut(), level, &buf); > + }); > + if result.is_err() || *level == Level::ERROR { > + log_to_syslog(&mut self.syslog_logger.lock().unwrap(), level, &buf); Also could do the .expect with an explanatory message here > + } > + } > +} > + > +fn log_to_syslog( > + logger: &mut syslog::Logger, > + level: &Level, > + buf: &String, > +) { > + let _ = match *level { > + Level::ERROR => logger.err(buf), > + Level::WARN => logger.warning(buf), > + Level::INFO => logger.info(buf), > + Level::DEBUG => logger.debug(buf), > + Level::TRACE => logger.debug(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)), You could inline these vars :) > + }; > +} > + > +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 94330ff1..2bfea4a0 100644 > --- a/proxmox-rest-server/Cargo.toml > +++ b/proxmox-rest-server/Cargo.toml > @@ -34,6 +34,7 @@ tokio-openssl.workspace = true > tokio-stream.workspace = true > tower-service.workspace = true > url.workspace = true > +tracing.workspace = true please keep the alphabetic order :) > > 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 Same here > > [features] > default = [] -- - Lukas _______________________________________________ pbs-devel mailing list pbs-devel@lists.proxmox.com https://lists.proxmox.com/cgi-bin/mailman/listinfo/pbs-devel