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 A53CA1FF2A7 for ; Mon, 1 Jul 2024 11:27:07 +0200 (CEST) Received: from firstgate.proxmox.com (localhost [127.0.0.1]) by firstgate.proxmox.com (Proxmox) with ESMTP id 49F2131D9D; Mon, 1 Jul 2024 11:27:21 +0200 (CEST) From: Gabriel Goller To: pbs-devel@lists.proxmox.com Date: Mon, 1 Jul 2024 11:26:30 +0200 Message-ID: <20240701092642.106030-2-g.goller@proxmox.com> X-Mailer: git-send-email 2.43.0 In-Reply-To: <20240701092642.106030-1-g.goller@proxmox.com> References: <20240701092642.106030-1-g.goller@proxmox.com> MIME-Version: 1.0 X-SPAM-LEVEL: Spam detection results: 0 AWL -0.057 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 Subject: [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 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 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 --- 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 | 151 +++++++++++++++++++++++++++++++ proxmox-log/src/lib.rs | 52 +++++++++++ proxmox-log/src/tasklog_layer.rs | 59 ++++++++++++ proxmox-rest-server/Cargo.toml | 2 + 10 files changed, 375 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/tasklog_layer.rs diff --git a/Cargo.toml b/Cargo.toml index ef45bb368704..fef95449b4d1 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -18,6 +18,7 @@ members = [ "proxmox-io", "proxmox-lang", "proxmox-ldap", + "proxmox-log", "proxmox-login", "proxmox-metrics", "proxmox-network-api", @@ -103,6 +104,10 @@ tokio = "1.6" tokio-openssl = "0.6.1" tokio-stream = "0.1.0" tower-service = "0.3.0" +tracing = "0.1" +tracing-journald = "0.3.0" +tracing-log = { version = "0.1.3", default-features = false } +tracing-subscriber = "0.3.16" url = "2.2" walkdir = "2" webauthn-rs = "0.3" @@ -119,6 +124,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.1.0", path = "proxmox-io" } proxmox-lang = { version = "1.3", 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.2.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 000000000000..050d9cce2122 --- /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 +nix.workspace = true +log.workspace = true +tracing.workspace = true +tracing-journald.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 000000000000..3661bae92772 --- /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 000000000000..d48b31800deb --- /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-tracing-journald-0.3+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-tracing-journald-0.3+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 000000000000..b227c290e25e --- /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 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 { + ($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(); + + 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 @@ -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