From 22a9ffac1de7f14f8912688f5255189160927f3b Mon Sep 17 00:00:00 2001 From: James Bornholt Date: Mon, 17 Jul 2023 23:41:22 -0500 Subject: [PATCH 1/5] Move logging module into its own file No code changes, just relocating the module in preparation for the next commit. Signed-off-by: James Bornholt --- mountpoint-s3/src/lib.rs | 1 + mountpoint-s3/src/logging.rs | 122 +++++++++++++++++++++++++++++++ mountpoint-s3/src/main.rs | 135 ++--------------------------------- 3 files changed, 128 insertions(+), 130 deletions(-) create mode 100644 mountpoint-s3/src/logging.rs diff --git a/mountpoint-s3/src/lib.rs b/mountpoint-s3/src/lib.rs index c9812d77d..b01dfa273 100644 --- a/mountpoint-s3/src/lib.rs +++ b/mountpoint-s3/src/lib.rs @@ -1,6 +1,7 @@ pub mod fs; pub mod fuse; mod inode; +pub mod logging; pub mod metrics; pub mod prefetch; pub mod prefix; diff --git a/mountpoint-s3/src/logging.rs b/mountpoint-s3/src/logging.rs new file mode 100644 index 000000000..4cb97bf6f --- /dev/null +++ b/mountpoint-s3/src/logging.rs @@ -0,0 +1,122 @@ +use std::backtrace::Backtrace; +use std::fs::{DirBuilder, OpenOptions}; +use std::os::unix::fs::DirBuilderExt; +use std::os::unix::prelude::OpenOptionsExt; +use std::panic::{self, PanicInfo}; +use std::path::Path; +use std::thread; + +use crate::metrics::metrics_tracing_span_layer; +use anyhow::Context; +use mountpoint_s3_crt::common::rust_log_adapter::RustLogAdapter; +use time::format_description::FormatItem; +use time::macros; +use time::OffsetDateTime; +use tracing_subscriber::{ + filter::EnvFilter, filter::LevelFilter, layer::SubscriberExt, util::SubscriberInitExt, Layer, +}; + +/// Set up all our logging infrastructure. +/// +/// This method: +/// - initializes the `tracing` subscriber for capturing log output +/// - sets up the logging adapters for the CRT and for metrics +/// - installs a panic hook to capture panics and log them with `tracing` +pub fn init_logging(is_foreground: bool, log_directory: Option<&Path>) -> anyhow::Result<()> { + init_tracing_subscriber(is_foreground, log_directory)?; + install_panic_hook(); + Ok(()) +} + +fn tracing_panic_hook(panic_info: &PanicInfo) { + let location = panic_info + .location() + .map(|l| format!("{}", l)) + .unwrap_or_else(|| String::from("")); + + let payload = panic_info.payload(); + let payload = if let Some(s) = payload.downcast_ref::<&'static str>() { + *s + } else if let Some(s) = payload.downcast_ref::() { + s.as_str() + } else { + "" + }; + + let thd = thread::current(); + + let backtrace = Backtrace::force_capture(); + + tracing::error!("panic on {thd:?} at {location}: {payload}"); + tracing::error!("backtrace:\n{backtrace}"); +} + +fn install_panic_hook() { + let old_hook = panic::take_hook(); + panic::set_hook(Box::new(move |panic_info| { + tracing_panic_hook(panic_info); + old_hook(panic_info); + })) +} + +fn init_tracing_subscriber(is_foreground: bool, log_directory: Option<&Path>) -> anyhow::Result<()> { + /// Create the logging config from the RUST_LOG environment variable or the default config if + /// that variable is unset. We do this in a function because [EnvFilter] isn't [Clone] and we + /// need a second copy of it in the foreground case to replicate logs to stdout. + fn create_env_filter() -> EnvFilter { + EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new("info,awscrt=off,fuser=error")) + } + let env_filter = create_env_filter(); + + // Don't create the files or subscribers if we'll never emit any logs + if env_filter.max_level_hint() == Some(LevelFilter::OFF) { + return Ok(()); + } + + RustLogAdapter::try_init().context("failed to initialize CRT logger")?; + + let file_layer = if let Some(path) = log_directory { + const LOG_FILE_NAME_FORMAT: &[FormatItem<'static>] = + macros::format_description!("mountpoint-s3-[year]-[month]-[day]T[hour]-[minute]-[second]Z.log"); + let filename = OffsetDateTime::now_utc() + .format(LOG_FILE_NAME_FORMAT) + .context("couldn't format log file name")?; + + // log directories and files created by Mountpoint should not be accessible by other users + let mut dir_builder = DirBuilder::new(); + dir_builder.recursive(true).mode(0o750); + let mut file_options = OpenOptions::new(); + file_options.mode(0o640).write(true).create(true); + + dir_builder.create(path).context("failed to create log folder")?; + let file = file_options + .open(path.join(filename)) + .context("failed to create log file")?; + + let file_layer = tracing_subscriber::fmt::layer() + .with_ansi(false) + .with_writer(file) + .with_filter(env_filter); + Some(file_layer) + } else { + None + }; + + let console_layer = if is_foreground { + let fmt_layer = tracing_subscriber::fmt::layer() + .with_ansi(supports_color::on(supports_color::Stream::Stdout).is_some()) + .with_filter(create_env_filter()); + Some(fmt_layer) + } else { + None + }; + + let registry = tracing_subscriber::registry() + .with(console_layer) + .with(file_layer) + .with(metrics_tracing_span_layer()); + + registry.init(); + + Ok(()) +} diff --git a/mountpoint-s3/src/main.rs b/mountpoint-s3/src/main.rs index 175cdebfb..955e0926d 100644 --- a/mountpoint-s3/src/main.rs +++ b/mountpoint-s3/src/main.rs @@ -1,6 +1,6 @@ use std::fs::File; use std::io::{Read, Write}; -use std::os::unix::prelude::{FromRawFd, OpenOptionsExt}; +use std::os::unix::prelude::FromRawFd; use std::path::{Path, PathBuf}; use std::time::Duration; @@ -10,6 +10,7 @@ use fuser::{MountOption, Session}; use mountpoint_s3::fs::S3FilesystemConfig; use mountpoint_s3::fuse::session::FuseSession; use mountpoint_s3::fuse::S3FuseFilesystem; +use mountpoint_s3::logging::init_logging; use mountpoint_s3::metrics::MetricsSink; use mountpoint_s3::prefix::Prefix; use mountpoint_s3_client::{ @@ -22,130 +23,6 @@ use regex::Regex; mod build_info; -mod logging { - use super::*; - - use std::backtrace::Backtrace; - use std::fs::{DirBuilder, OpenOptions}; - use std::os::unix::fs::DirBuilderExt; - use std::panic::{self, PanicInfo}; - use std::thread; - - use mountpoint_s3::metrics::metrics_tracing_span_layer; - use mountpoint_s3_crt::common::rust_log_adapter::RustLogAdapter; - use time::format_description::FormatItem; - use time::macros; - use time::OffsetDateTime; - use tracing_subscriber::{ - filter::EnvFilter, filter::LevelFilter, layer::SubscriberExt, util::SubscriberInitExt, Layer, - }; - - /// Set up all our logging infrastructure. - /// - /// This method: - /// - initializes the `tracing` subscriber for capturing log output - /// - sets up the logging adapters for the CRT and for metrics - /// - installs a panic hook to capture panics and log them with `tracing` - pub(super) fn init_logging(is_foreground: bool, log_directory: Option<&Path>) -> anyhow::Result<()> { - init_tracing_subscriber(is_foreground, log_directory)?; - install_panic_hook(); - Ok(()) - } - - fn tracing_panic_hook(panic_info: &PanicInfo) { - let location = panic_info - .location() - .map(|l| format!("{}", l)) - .unwrap_or_else(|| String::from("")); - - let payload = panic_info.payload(); - let payload = if let Some(s) = payload.downcast_ref::<&'static str>() { - *s - } else if let Some(s) = payload.downcast_ref::() { - s.as_str() - } else { - "" - }; - - let thd = thread::current(); - - let backtrace = Backtrace::force_capture(); - - tracing::error!("panic on {thd:?} at {location}: {payload}"); - tracing::error!("backtrace:\n{backtrace}"); - } - - fn install_panic_hook() { - let old_hook = panic::take_hook(); - panic::set_hook(Box::new(move |panic_info| { - tracing_panic_hook(panic_info); - old_hook(panic_info); - })) - } - - fn init_tracing_subscriber(is_foreground: bool, log_directory: Option<&Path>) -> anyhow::Result<()> { - /// Create the logging config from the RUST_LOG environment variable or the default config if - /// that variable is unset. We do this in a function because [EnvFilter] isn't [Clone] and we - /// need a second copy of it in the foreground case to replicate logs to stdout. - fn create_env_filter() -> EnvFilter { - EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new("info,awscrt=off,fuser=error")) - } - let env_filter = create_env_filter(); - - // Don't create the files or subscribers if we'll never emit any logs - if env_filter.max_level_hint() == Some(LevelFilter::OFF) { - return Ok(()); - } - - RustLogAdapter::try_init().context("failed to initialize CRT logger")?; - - let file_layer = if let Some(path) = log_directory { - const LOG_FILE_NAME_FORMAT: &[FormatItem<'static>] = - macros::format_description!("mountpoint-s3-[year]-[month]-[day]T[hour]-[minute]-[second]Z.log"); - let filename = OffsetDateTime::now_utc() - .format(LOG_FILE_NAME_FORMAT) - .context("couldn't format log file name")?; - - // log directories and files created by Mountpoint should not be accessible by other users - let mut dir_builder = DirBuilder::new(); - dir_builder.recursive(true).mode(0o750); - let mut file_options = OpenOptions::new(); - file_options.mode(0o640).write(true).create(true); - - dir_builder.create(path).context("failed to create log folder")?; - let file = file_options - .open(path.join(filename)) - .context("failed to create log file")?; - - let file_layer = tracing_subscriber::fmt::layer() - .with_ansi(false) - .with_writer(file) - .with_filter(env_filter); - Some(file_layer) - } else { - None - }; - - let console_layer = if is_foreground { - let fmt_layer = tracing_subscriber::fmt::layer() - .with_ansi(supports_color::on(supports_color::Stream::Stdout).is_some()) - .with_filter(create_env_filter()); - Some(fmt_layer) - } else { - None - }; - - let registry = tracing_subscriber::registry() - .with(console_layer) - .with(file_layer) - .with(metrics_tracing_span_layer()); - - registry.init(); - - Ok(()) - } -} - const CLIENT_OPTIONS_HEADER: &str = "Client options"; const MOUNT_OPTIONS_HEADER: &str = "Mount options"; const BUCKET_OPTIONS_HEADER: &str = "Bucket options"; @@ -318,8 +195,7 @@ fn main() -> anyhow::Result<()> { let args = CliArgs::parse(); if args.foreground { - logging::init_logging(args.foreground, args.log_directory.as_deref()) - .context("failed to initialize logging")?; + init_logging(args.foreground, args.log_directory.as_deref()).context("failed to initialize logging")?; let _metrics = MetricsSink::init(); @@ -340,7 +216,7 @@ fn main() -> anyhow::Result<()> { match pid.expect("Failed to fork mount process") { ForkResult::Child => { let child_args = CliArgs::parse(); - logging::init_logging(child_args.foreground, child_args.log_directory.as_deref()) + init_logging(child_args.foreground, child_args.log_directory.as_deref()) .context("failed to initialize logging")?; let _metrics = MetricsSink::init(); @@ -374,8 +250,7 @@ fn main() -> anyhow::Result<()> { } } ForkResult::Parent { child } => { - logging::init_logging(args.foreground, args.log_directory.as_deref()) - .context("failed to initialize logging")?; + init_logging(args.foreground, args.log_directory.as_deref()).context("failed to initialize logging")?; // close unused file descriptor, we only read from this end. nix::unistd::close(write_fd).context("Failed to close unused file descriptor")?; From 7e7a4c01427e7554c50471be9f0b9f152e794b95 Mon Sep 17 00:00:00 2001 From: James Bornholt Date: Mon, 17 Jul 2023 23:42:21 -0500 Subject: [PATCH 2/5] Emit warning-level logs to syslog when log directory is unset Signed-off-by: James Bornholt --- Cargo.lock | 51 +++++ mountpoint-s3-client/src/s3_crt_client.rs | 3 +- mountpoint-s3/Cargo.toml | 1 + mountpoint-s3/src/logging.rs | 21 ++- mountpoint-s3/src/logging/syslog.rs | 217 ++++++++++++++++++++++ 5 files changed, 289 insertions(+), 4 deletions(-) create mode 100644 mountpoint-s3/src/logging/syslog.rs diff --git a/Cargo.lock b/Cargo.lock index d738cac89..e1a062c69 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1168,6 +1168,15 @@ dependencies = [ "libc", ] +[[package]] +name = "error-chain" +version = "0.12.4" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "2d2f06b9cac1506ece98fe3231e3cc9c4410ec3d5b1f24ae1c8946f0742cdefc" +dependencies = [ + "version_check", +] + [[package]] name = "event-listener" version = "2.5.3" @@ -1506,6 +1515,17 @@ dependencies = [ "digest", ] +[[package]] +name = "hostname" +version = "0.3.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "3c731c3e10504cc8ed35cfe2f1db4c9274c3d35fa486e3b31df46f068ef3e867" +dependencies = [ + "libc", + "match_cfg", + "winapi", +] + [[package]] name = "http" version = "0.2.9" @@ -1789,6 +1809,12 @@ version = "0.4.19" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "b06a4cde4c0f271a446782e3eff8de789548ce57dbc8eca9292c27f4a42004b4" +[[package]] +name = "match_cfg" +version = "0.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ffbee8634e0d45d258acb448e7eaab3fce7a0a467395d4d9f228e3c1f01fb2e4" + [[package]] name = "matchers" version = "0.1.0" @@ -1918,6 +1944,7 @@ dependencies = [ "sha2", "shuttle", "supports-color", + "syslog", "tempfile", "test-case", "thiserror", @@ -2074,6 +2101,15 @@ dependencies = [ "libc", ] +[[package]] +name = "num_threads" +version = "0.1.6" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "2819ce041d2ee131036f4fc9d6ae7ae125a3a40e97ba64d04fe799ad9dabbb44" +dependencies = [ + "libc", +] + [[package]] name = "object" version = "0.30.4" @@ -2928,6 +2964,19 @@ dependencies = [ "unicode-ident", ] +[[package]] +name = "syslog" +version = "6.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "7434e95bcccce1215d30f4bf84fe8c00e8de1b9be4fb736d747ca53d36e7f96f" +dependencies = [ + "error-chain", + "hostname", + "libc", + "log", + "time", +] + [[package]] name = "tap" version = "1.0.1" @@ -3028,6 +3077,8 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "ea9e1b3cf1243ae005d9e74085d4d542f3125458f3a81af210d901dcd7411efd" dependencies = [ "itoa", + "libc", + "num_threads", "serde", "time-core", "time-macros", diff --git a/mountpoint-s3-client/src/s3_crt_client.rs b/mountpoint-s3-client/src/s3_crt_client.rs index 038dafaee..38e4334c7 100644 --- a/mountpoint-s3-client/src/s3_crt_client.rs +++ b/mountpoint-s3-client/src/s3_crt_client.rs @@ -40,7 +40,8 @@ use crate::s3_crt_client::put_object::S3PutObjectRequest; macro_rules! request_span { ($self:expr, $method:expr) => {{ let counter = $self.next_request_counter(); - tracing::debug_span!($method, id = counter) + // Request failures are emitted at warning verbosity, so emit their spans there too + tracing::warn_span!($method, id = counter) }}; } diff --git a/mountpoint-s3/Cargo.toml b/mountpoint-s3/Cargo.toml index 5ba81f601..3067cfdea 100644 --- a/mountpoint-s3/Cargo.toml +++ b/mountpoint-s3/Cargo.toml @@ -24,6 +24,7 @@ metrics = "0.20.1" once_cell = "1.16.0" regex = "1.7.1" supports-color = "1.3.0" +syslog = "6.1.0" thiserror = "1.0.34" tracing = { version = "0.1.35", default-features = false, features = ["std", "log"] } tracing-subscriber = { version = "0.3.14", features = ["fmt", "env-filter"] } diff --git a/mountpoint-s3/src/logging.rs b/mountpoint-s3/src/logging.rs index 4cb97bf6f..616d70486 100644 --- a/mountpoint-s3/src/logging.rs +++ b/mountpoint-s3/src/logging.rs @@ -12,9 +12,13 @@ use mountpoint_s3_crt::common::rust_log_adapter::RustLogAdapter; use time::format_description::FormatItem; use time::macros; use time::OffsetDateTime; -use tracing_subscriber::{ - filter::EnvFilter, filter::LevelFilter, layer::SubscriberExt, util::SubscriberInitExt, Layer, -}; +use tracing_subscriber::filter::{EnvFilter, Filtered, LevelFilter}; +use tracing_subscriber::layer::SubscriberExt; +use tracing_subscriber::util::SubscriberInitExt; +use tracing_subscriber::{Layer, Registry}; + +mod syslog; +use self::syslog::SyslogLayer; /// Set up all our logging infrastructure. /// @@ -102,6 +106,16 @@ fn init_tracing_subscriber(is_foreground: bool, log_directory: Option<&Path>) -> None }; + let syslog_layer: Option> = if log_directory.is_none() { + // TODO decide how to configure the filter for syslog + let env_filter = EnvFilter::new("warn,awscrt=off"); + // Don't fail if syslog isn't available on the system, since it's a default + let syslog_layer = SyslogLayer::new().ok(); + syslog_layer.map(|l| l.with_filter(env_filter)) + } else { + None + }; + let console_layer = if is_foreground { let fmt_layer = tracing_subscriber::fmt::layer() .with_ansi(supports_color::on(supports_color::Stream::Stdout).is_some()) @@ -112,6 +126,7 @@ fn init_tracing_subscriber(is_foreground: bool, log_directory: Option<&Path>) -> }; let registry = tracing_subscriber::registry() + .with(syslog_layer) .with(console_layer) .with(file_layer) .with(metrics_tracing_span_layer()); diff --git a/mountpoint-s3/src/logging/syslog.rs b/mountpoint-s3/src/logging/syslog.rs new file mode 100644 index 000000000..a9b2c3f1e --- /dev/null +++ b/mountpoint-s3/src/logging/syslog.rs @@ -0,0 +1,217 @@ +use std::fmt::Write; +use std::sync::Mutex; + +use syslog::{Facility, Formatter3164, Logger, LoggerBackend}; +use tracing::field::{Field, Visit}; +use tracing::span::{Attributes, Record}; +use tracing::{Event, Id, Level, Subscriber}; +use tracing_subscriber::layer::Context; +use tracing_subscriber::registry::LookupSpan; +use tracing_subscriber::Layer; + +/// A [tracing_subscribrer::Layer] that emits log events to syslog. This layer does no filtering, +/// and so should be paired with a [tracing_subscriber::Filter]. +pub struct SyslogLayer { + logger: Mutex>, +} + +impl SyslogLayer { + pub fn new() -> Result { + let formatter = Self::formatter(); + let logger = syslog::unix(formatter)?; + Ok(Self { + logger: Mutex::new(logger), + }) + } +} + +impl SyslogLayer { + #[cfg(test)] + pub fn new_generic(backend: B) -> Self { + let formatter = Self::formatter(); + let logger = Logger::new(backend, formatter); + Self { + logger: Mutex::new(logger), + } + } + + fn formatter() -> Formatter3164 { + Formatter3164 { + facility: Facility::LOG_USER, + hostname: None, + process: "mount-s3".into(), + pid: unsafe { libc::getpid() as u32 }, + } + } +} + +impl Layer for SyslogLayer +where + S: Subscriber + for<'a> LookupSpan<'a>, + B: std::io::Write + 'static, +{ + fn on_new_span(&self, attrs: &Attributes<'_>, id: &Id, ctx: Context<'_, S>) { + let span = ctx.span(id).expect("span must exist"); + let mut extensions = span.extensions_mut(); + if extensions.get_mut::().is_none() { + let mut fields = String::new(); + FormatFields::format_attributes(&mut fields, attrs); + extensions.insert(FormattedFields(fields)); + } + } + + fn on_record(&self, id: &Id, values: &Record<'_>, ctx: Context<'_, S>) { + let span = ctx.span(id).expect("span must exist"); + let mut extensions = span.extensions_mut(); + if let Some(fields) = extensions.get_mut::() { + FormatFields::format_record(&mut fields.0, values); + return; + } + let mut fields = String::new(); + FormatFields::format_record(&mut fields, values); + extensions.insert(FormattedFields(fields)); + } + + fn on_event(&self, event: &Event<'_>, ctx: Context<'_, S>) { + // No need to do any filtering -- we assume this layer is paired with a filter. So just + // build the message and ship it. + let metadata = event.metadata(); + let mut message = format!("[{}] {}: ", metadata.level(), metadata.target()); + // First deal with any spans + if let Some(scope) = ctx.event_scope(event) { + let mut seen = false; + for span in scope.from_root() { + seen = true; + let _ = write!(message, "{}", span.metadata().name()); + if let Some(fields) = span.extensions().get::() { + let _ = write!(message, "{{{}}}", fields.0); + } + let _ = write!(message, ":"); + } + if seen { + let _ = write!(message, " "); + } + } + // Now deal with the event + FormatFields::format_event(&mut message, event); + + let mut logger = self.logger.lock().unwrap(); + let _ = match *event.metadata().level() { + Level::ERROR => logger.err(message), + Level::WARN => logger.warning(message), + Level::INFO => logger.info(message), + Level::DEBUG => logger.debug(message), + Level::TRACE => logger.debug(message), + }; + } +} + +/// Convert `tracing` events/attributes into strings with a visitor pattern +struct FormatFields<'a> { + buf: &'a mut String, +} + +impl<'a> FormatFields<'a> { + fn format_event(buf: &'a mut String, event: &Event<'_>) { + let mut fmt = Self { buf }; + event.record(&mut fmt); + } + + fn format_attributes(buf: &'a mut String, attrs: &Attributes<'_>) { + let mut fmt = Self { buf }; + attrs.record(&mut fmt); + } + + fn format_record(buf: &'a mut String, record: &Record<'_>) { + let mut fmt = Self { buf }; + record.record(&mut fmt); + } +} + +impl Visit for FormatFields<'_> { + fn record_debug(&mut self, field: &Field, value: &dyn std::fmt::Debug) { + if field.name() == "message" { + let _ = write!(self.buf, "{:?}", value); + } else { + if !self.buf.is_empty() { + let _ = write!(self.buf, " "); + } + let _ = write!(self.buf, "{}={:?}", field.name(), value); + } + } + + fn record_str(&mut self, field: &Field, value: &str) { + if field.name() == "message" { + let _ = write!(self.buf, "{}", value); + } else { + if !self.buf.is_empty() { + let _ = write!(self.buf, " "); + } + let _ = write!(self.buf, "{}={}", field.name(), value); + } + } +} + +/// A newtype to store the formatted representation of a `tracing` Span's fields +struct FormattedFields(String); + +#[cfg(test)] +mod tests { + use std::sync::Arc; + + use super::*; + + use tracing_subscriber::layer::SubscriberExt; + + #[derive(Debug, Clone, Default)] + struct LockedWriter { + inner: Arc>>, + } + + impl std::io::Write for LockedWriter { + fn write(&mut self, buf: &[u8]) -> std::io::Result { + let mut inner = self.inner.lock().unwrap(); + inner.extend_from_slice(buf); + Ok(buf.len()) + } + + fn flush(&mut self) -> std::io::Result<()> { + Ok(()) + } + } + + #[test] + fn test_syslog_layer() { + let buf = LockedWriter::default(); + let layer = SyslogLayer::new_generic(buf.clone()); + let subscriber = tracing_subscriber::registry().with(layer); + tracing::subscriber::with_default(subscriber, || { + let span = tracing::info_span!("span1", field1 = 1, field2 = 2, "msg1={:?}", 1); + let _enter = span.enter(); + let span2 = tracing::warn_span!("span2", field3 = 3, field4 = 4, "msg2={:?}", 2); + let _enter2 = span2.enter(); + tracing::info!(field5 = 5, field6 = 6, "msg3={:?}", 3); + }); + let vec = std::mem::replace(&mut *buf.inner.lock().unwrap(), Vec::new()); + let output = String::from_utf8(vec).unwrap(); + // The actual output is syslog-formatted, so includes the current time and PID. Let's just + // check the parts of the payload we really care about. + let expected = "mountpoint_s3::logging::syslog::tests: span1{msg1=1 field1=1 field2=2}:span2{msg2=2 field3=3 field4=4}: msg3=3 field5=5 field6=6"; + assert!( + output.ends_with(expected), + "expected payload {:?} to end with {:?}", + output, + expected + ); + assert!( + output.contains("mount-s3"), + "expected payload {:?} to contain mount-s3", + output + ); + assert!( + output.starts_with("<14>"), + "expected payload {:?} to start with syslog PRI <14>", + output + ); + } +} From e6ec8ca3a9a69cc200af8fa2a90d9044587adc25 Mon Sep 17 00:00:00 2001 From: James Bornholt Date: Tue, 18 Jul 2023 19:52:57 +0000 Subject: [PATCH 3/5] Appease clippy Signed-off-by: James Bornholt --- mountpoint-s3/src/logging/syslog.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/mountpoint-s3/src/logging/syslog.rs b/mountpoint-s3/src/logging/syslog.rs index a9b2c3f1e..4455fadd8 100644 --- a/mountpoint-s3/src/logging/syslog.rs +++ b/mountpoint-s3/src/logging/syslog.rs @@ -192,7 +192,7 @@ mod tests { let _enter2 = span2.enter(); tracing::info!(field5 = 5, field6 = 6, "msg3={:?}", 3); }); - let vec = std::mem::replace(&mut *buf.inner.lock().unwrap(), Vec::new()); + let vec = std::mem::take(&mut *buf.inner.lock().unwrap()); let output = String::from_utf8(vec).unwrap(); // The actual output is syslog-formatted, so includes the current time and PID. Let's just // check the parts of the payload we really care about. From d68a8c4aa381e82c590426b957bb15ff3e1c4081 Mon Sep 17 00:00:00 2001 From: James Bornholt Date: Tue, 18 Jul 2023 20:01:49 +0000 Subject: [PATCH 4/5] Document a little better Signed-off-by: James Bornholt --- mountpoint-s3/src/logging/syslog.rs | 14 +++++++++++--- 1 file changed, 11 insertions(+), 3 deletions(-) diff --git a/mountpoint-s3/src/logging/syslog.rs b/mountpoint-s3/src/logging/syslog.rs index 4455fadd8..eb9b26b1d 100644 --- a/mountpoint-s3/src/logging/syslog.rs +++ b/mountpoint-s3/src/logging/syslog.rs @@ -45,6 +45,9 @@ impl SyslogLayer { } } +// This is a stripped down version of [tracing_subscribers::fmt::Layer] that skips some tracing +// stuff we don't use, like timings and span enter/exit events. +// https://github.com/tokio-rs/tracing/blob/0114ec1cf56e01e79b2e429e77c660457711d263/tracing-subscriber/src/fmt/fmt_layer.rs#L786 impl Layer for SyslogLayer where S: Subscriber + for<'a> LookupSpan<'a>, @@ -52,6 +55,8 @@ where { fn on_new_span(&self, attrs: &Attributes<'_>, id: &Id, ctx: Context<'_, S>) { let span = ctx.span(id).expect("span must exist"); + // Format the span fields now (we won't have access to them at [on_event] time) and stash + // the result in the `extensions` bag to access from [on_event] let mut extensions = span.extensions_mut(); if extensions.get_mut::().is_none() { let mut fields = String::new(); @@ -63,6 +68,7 @@ where fn on_record(&self, id: &Id, values: &Record<'_>, ctx: Context<'_, S>) { let span = ctx.span(id).expect("span must exist"); let mut extensions = span.extensions_mut(); + // Update the fields in place if we already formatted them at [on_new_span] time if let Some(fields) = extensions.get_mut::() { FormatFields::format_record(&mut fields.0, values); return; @@ -77,7 +83,8 @@ where // build the message and ship it. let metadata = event.metadata(); let mut message = format!("[{}] {}: ", metadata.level(), metadata.target()); - // First deal with any spans + // First deal with any spans by walking up the span tree and adding each span's formatted + // representation to the message if let Some(scope) = ctx.event_scope(event) { let mut seen = false; for span in scope.from_root() { @@ -92,7 +99,7 @@ where let _ = write!(message, " "); } } - // Now deal with the event + // Now deal with the event itself FormatFields::format_event(&mut message, event); let mut logger = self.logger.lock().unwrap(); @@ -101,12 +108,13 @@ where Level::WARN => logger.warning(message), Level::INFO => logger.info(message), Level::DEBUG => logger.debug(message), + // syslog has no trace level, so just re-use debug (the lowest syslog level) Level::TRACE => logger.debug(message), }; } } -/// Convert `tracing` events/attributes into strings with a visitor pattern +/// Convert `tracing` events/attributes into strings with a visitor pattern. struct FormatFields<'a> { buf: &'a mut String, } From 14e80fddac34128ac4c0571b5bf028a5ec495e20 Mon Sep 17 00:00:00 2001 From: James Bornholt Date: Wed, 19 Jul 2023 16:00:47 +0000 Subject: [PATCH 5/5] PR feedback Signed-off-by: James Bornholt --- mountpoint-s3-client/src/s3_crt_client.rs | 3 +- mountpoint-s3/src/logging/syslog.rs | 57 ++++++++++++++++------- 2 files changed, 42 insertions(+), 18 deletions(-) diff --git a/mountpoint-s3-client/src/s3_crt_client.rs b/mountpoint-s3-client/src/s3_crt_client.rs index 38e4334c7..038dafaee 100644 --- a/mountpoint-s3-client/src/s3_crt_client.rs +++ b/mountpoint-s3-client/src/s3_crt_client.rs @@ -40,8 +40,7 @@ use crate::s3_crt_client::put_object::S3PutObjectRequest; macro_rules! request_span { ($self:expr, $method:expr) => {{ let counter = $self.next_request_counter(); - // Request failures are emitted at warning verbosity, so emit their spans there too - tracing::warn_span!($method, id = counter) + tracing::debug_span!($method, id = counter) }}; } diff --git a/mountpoint-s3/src/logging/syslog.rs b/mountpoint-s3/src/logging/syslog.rs index eb9b26b1d..11e1ebe03 100644 --- a/mountpoint-s3/src/logging/syslog.rs +++ b/mountpoint-s3/src/logging/syslog.rs @@ -1,3 +1,8 @@ +//! Provides a subscriber that sends [tracing] logs to `syslog` over a Unix socket. +//! +//! We do this by implementing a [tracing_subscriber::Layer] that listens for [tracing] events and +//! emits them to a syslog socket that was opened when the layer was created. + use std::fmt::Write; use std::sync::Mutex; @@ -9,7 +14,7 @@ use tracing_subscriber::layer::Context; use tracing_subscriber::registry::LookupSpan; use tracing_subscriber::Layer; -/// A [tracing_subscribrer::Layer] that emits log events to syslog. This layer does no filtering, +/// A [tracing_subscriber::Layer] that emits log events to syslog. This layer does no filtering, /// and so should be paired with a [tracing_subscriber::Filter]. pub struct SyslogLayer { logger: Mutex>, @@ -40,49 +45,68 @@ impl SyslogLayer { facility: Facility::LOG_USER, hostname: None, process: "mount-s3".into(), - pid: unsafe { libc::getpid() as u32 }, + pid: std::process::id(), } } } -// This is a stripped down version of [tracing_subscribers::fmt::Layer] that skips some tracing -// stuff we don't use, like timings and span enter/exit events. -// https://github.com/tokio-rs/tracing/blob/0114ec1cf56e01e79b2e429e77c660457711d263/tracing-subscriber/src/fmt/fmt_layer.rs#L786 +/// Implement a [tracing_subscriber::Layer] that will emit [tracing] events to syslog. +/// +/// [tracing] has both "spans", a period of time during program execution, and "events", something +/// that happens at a moment in time. We use spans to remember information for the duration of an +/// interesting context -- for example, a GetObject request might have a span for the duration of +/// the request that records the key being retrieved. We use events to record interesting things +/// that happened -- for example, the GetObject request succeeded or failed. When an event is +/// generated, we can look up all the open spans at that moment in time to recover all the +/// interesting context for the event. +/// +/// This layer listens for new spans and records the information associated with them (which tracing +/// allows to be mutated via [on_record]). Then it listens for events, and when an event is +/// received, it builds a message to send to syslog by combining the previously recorded information +/// for all open spans with the information for the event. +/// +/// This is a stripped down version of [tracing_subscribers::fmt::Layer] that skips some tracing +/// stuff we don't need, like timings and span enter/exit events. +/// https://github.com/tokio-rs/tracing/blob/0114ec1cf56e01e79b2e429e77c660457711d263/tracing-subscriber/src/fmt/fmt_layer.rs#L786 impl Layer for SyslogLayer where S: Subscriber + for<'a> LookupSpan<'a>, B: std::io::Write + 'static, { + // A new span has been constructed -- record its fields for use in [on_event] fn on_new_span(&self, attrs: &Attributes<'_>, id: &Id, ctx: Context<'_, S>) { let span = ctx.span(id).expect("span must exist"); // Format the span fields now (we won't have access to them at [on_event] time) and stash // the result in the `extensions` bag to access from [on_event] let mut extensions = span.extensions_mut(); if extensions.get_mut::().is_none() { - let mut fields = String::new(); - FormatFields::format_attributes(&mut fields, attrs); - extensions.insert(FormattedFields(fields)); + let mut fields = FormattedFields(String::new()); + FormatFields::format_attributes(&mut fields.0, attrs); + extensions.insert(fields); } } + // An existing span is being mutated with new values -- update the recorded fields fn on_record(&self, id: &Id, values: &Record<'_>, ctx: Context<'_, S>) { let span = ctx.span(id).expect("span must exist"); let mut extensions = span.extensions_mut(); - // Update the fields in place if we already formatted them at [on_new_span] time + // Append the fields to the existing string if it exists (from [on_new_span]), otherwise + // store a new string if let Some(fields) = extensions.get_mut::() { FormatFields::format_record(&mut fields.0, values); - return; + } else { + let mut fields = FormattedFields(String::new()); + FormatFields::format_record(&mut fields.0, values); + extensions.insert(fields); } - let mut fields = String::new(); - FormatFields::format_record(&mut fields, values); - extensions.insert(FormattedFields(fields)); } + // An event has been emitted fn on_event(&self, event: &Event<'_>, ctx: Context<'_, S>) { // No need to do any filtering -- we assume this layer is paired with a filter. So just // build the message and ship it. let metadata = event.metadata(); - let mut message = format!("[{}] {}: ", metadata.level(), metadata.target()); + let mut message = format!("[{}] ", metadata.level()); // First deal with any spans by walking up the span tree and adding each span's formatted // representation to the message if let Some(scope) = ctx.event_scope(event) { @@ -99,6 +123,7 @@ where let _ = write!(message, " "); } } + let _ = write!(message, "{}: ", metadata.target()); // Now deal with the event itself FormatFields::format_event(&mut message, event); @@ -198,13 +223,13 @@ mod tests { let _enter = span.enter(); let span2 = tracing::warn_span!("span2", field3 = 3, field4 = 4, "msg2={:?}", 2); let _enter2 = span2.enter(); - tracing::info!(field5 = 5, field6 = 6, "msg3={:?}", 3); + tracing::info!(field5 = 5, field6 = 6, "this is a real {:?} message", "cool"); }); let vec = std::mem::take(&mut *buf.inner.lock().unwrap()); let output = String::from_utf8(vec).unwrap(); // The actual output is syslog-formatted, so includes the current time and PID. Let's just // check the parts of the payload we really care about. - let expected = "mountpoint_s3::logging::syslog::tests: span1{msg1=1 field1=1 field2=2}:span2{msg2=2 field3=3 field4=4}: msg3=3 field5=5 field6=6"; + let expected = "[INFO] span1{msg1=1 field1=1 field2=2}:span2{msg2=2 field3=3 field4=4}: mountpoint_s3::logging::syslog::tests: this is a real \"cool\" message field5=5 field6=6"; assert!( output.ends_with(expected), "expected payload {:?} to end with {:?}",