From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from firstgate.proxmox.com (firstgate.proxmox.com [IPv6:2a01:7e0:0:424::9]) by lore.proxmox.com (Postfix) with ESMTPS id 44A571FF3A0 for ; Thu, 13 Jun 2024 15:56:28 +0200 (CEST) Received: from firstgate.proxmox.com (localhost [127.0.0.1]) by firstgate.proxmox.com (Proxmox) with ESMTP id A9F4031E2E; Thu, 13 Jun 2024 15:57:05 +0200 (CEST) From: Gabriel Goller To: pbs-devel@lists.proxmox.com Date: Thu, 13 Jun 2024 15:56:14 +0200 Message-ID: <20240613135623.279167-2-g.goller@proxmox.com> X-Mailer: git-send-email 2.43.0 In-Reply-To: <20240613135623.279167-1-g.goller@proxmox.com> References: <20240613135623.279167-1-g.goller@proxmox.com> MIME-Version: 1.0 X-SPAM-LEVEL: Spam detection results: 0 AWL -0.059 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 T_SCC_BODY_TEXT_LINE -0.01 - Subject: [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" 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 +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>( + 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> { + 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) { + 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(); + } + + 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) + }; + 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); + } + } +} + +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) + .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); + } + } +} + +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)), + }; +} + +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 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