[pbs-devel] [PATCH proxmox v4 1/4] proxmox-log: add tracing infrastructure

[Gabriel Goller <g.goller@proxmox.com>]

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 <g.goller@proxmox.com>
---
 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 535d245..2dcb6bd 100644
--- a/Cargo.toml
+++ b/Cargo.toml
@@ -14,6 +14,7 @@ members = [
     "proxmox-io",
     "proxmox-lang",
     "proxmox-ldap",
+    "proxmox-log",
     "proxmox-login",
     "proxmox-metrics",
     "proxmox-notify",
@@ -87,11 +88,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"
@@ -106,6 +111,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-rest-server = { version = "0.5.2", path = "proxmox-rest-server" }
 proxmox-router = { version = "2.1.3", path = "proxmox-router" }
diff --git a/proxmox-log/Cargo.toml b/proxmox-log/Cargo.toml
new file mode 100644
index 0000000..14ca6c7
--- /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 0000000..3661bae
--- /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 <ggoller@luna.proxmox.com>  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 0000000..14b2376
--- /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 <!nocheck>,
+ rustc:native <!nocheck>,
+ libstd-rust-dev <!nocheck>,
+ librust-anyhow-1+default-dev <!nocheck>,
+ librust-log-0.4+default-dev (>= 0.4.17-~~) <!nocheck>,
+ librust-nix-0.26+default-dev (>= 0.26.1-~~) <!nocheck>,
+ librust-proxmox-sys-0.5+default-dev (>= 0.5.1-~~) <!nocheck>,
+ librust-proxmox-time-1+default-dev (>= 1.1.6-~~) <!nocheck>,
+ librust-syslog-6+default-dev <!nocheck>,
+ librust-tokio-1+default-dev (>= 1.6-~~) <!nocheck>,
+ librust-tokio-1+rt-multi-thread-dev (>= 1.6-~~) <!nocheck>,
+ librust-tracing-0.1+default-dev <!nocheck>,
+ librust-tracing-log-0.1-dev (>= 0.1.3-~~) <!nocheck>,
+ librust-tracing-subscriber-0.3+default-dev (>= 0.3.16-~~) <!nocheck>
+Maintainer: Proxmox Support Team <support@proxmox.com>
+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 0000000..b227c29
--- /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 <support@proxmox.com>
+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 <https://www.gnu.org/licenses/>.
diff --git a/proxmox-log/debian/debcargo.toml b/proxmox-log/debian/debcargo.toml
new file mode 100644
index 0000000..b7864cd
--- /dev/null
+++ b/proxmox-log/debian/debcargo.toml
@@ -0,0 +1,7 @@
+overlay = "."
+crate_src_path = ".."
+maintainer = "Proxmox Support Team <support@proxmox.com>"
+
+[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 0000000..c7e1d64
--- /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<P: AsRef<std::path::Path>>(
+        file_name: P,
+        options: FileLogOptions,
+    ) -> Result<Self, Error> {
+        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<P: AsRef<std::path::Path>>(
+        file_name: P,
+        options: &FileLogOptions,
+    ) -> Result<std::fs::File, Error> {
+        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<S: AsRef<str>>(&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<usize, std::io::Error> {
+        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 0000000..daaaede
--- /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<FileLogger>;
+    pub static WARN_COUNTER: Cell<u64> ;
+}
+
+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::<LevelFilter>() {
+            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 0000000..89437ca
--- /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<Mutex<syslog::Logger<LoggerBackend, Formatter3164>>>,
+}
+
+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<S: Subscriber> Layer<S> 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<LoggerBackend, Formatter3164>,
+    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 94330ff..2bfea4a 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