From 1a16f5a7d63e63b606f8cc21ad948803ef1a8245 Mon Sep 17 00:00:00 2001 From: Nick Mathewson Date: Fri, 7 Jan 2022 10:52:43 -0500 Subject: [PATCH] Tracing configuration for logfiles, per-target filters Previously we could only configure one global tracing filter that applied to stdout and journald. There was no support for log files, either. This patch fixes both issues, by substantially revising the configuration format: There are now separate filters for each log file, for journald, and for the console log. Because we want to allow multiple logfiles, they have to go into an array in the configuration. The configuration logic has grown a bit complicated in its types, since the tracing_subscriber crate would prefer to have the complete structure of tracing Layers known statically. That's fine when you know how many you have, and which kinds there will be, but for the runtime-configuration case we need to mess around with `Box`. I also had to switch from tracing_subscriber's EnvFilter to its Targets filter. It seems "EnvFilter" can only be applied as a Layer in itself, and won't work as a Filter on an individual Layer. Closes #166. Closes #170. --- Cargo.lock | 22 +++ crates/arti-config/src/arti_defaults.toml | 21 ++- crates/arti-config/src/lib.rs | 4 +- crates/arti-config/src/options.rs | 116 +++++++++++++-- crates/arti/Cargo.toml | 1 + crates/arti/src/main.rs | 2 +- crates/arti/src/trace.rs | 169 ++++++++++++++++++---- 7 files changed, 279 insertions(+), 56 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 84c91908e..488fcfde7 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -78,6 +78,7 @@ dependencies = [ "tor-rtcompat", "tor-socksproto", "tracing", + "tracing-appender", "tracing-journald", "tracing-subscriber", "winapi", @@ -618,6 +619,16 @@ dependencies = [ "cfg-if", ] +[[package]] +name = "crossbeam-channel" +version = "0.5.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "06ed27e177f16d65f0f0c22a213e17c696ace5dd64b14258b52f9417ccb52db4" +dependencies = [ + "cfg-if", + "crossbeam-utils", +] + [[package]] name = "crossbeam-queue" version = "0.3.2" @@ -3010,6 +3021,17 @@ dependencies = [ "tracing-core", ] +[[package]] +name = "tracing-appender" +version = "0.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "94571df2eae3ed4353815ea5a90974a594a1792d8782ff2cbcc9392d1101f366" +dependencies = [ + "crossbeam-channel", + "time", + "tracing-subscriber", +] + [[package]] name = "tracing-attributes" version = "0.1.18" diff --git a/crates/arti-config/src/arti_defaults.toml b/crates/arti-config/src/arti_defaults.toml index 9ac6c67be..192e5f363 100644 --- a/crates/arti-config/src/arti_defaults.toml +++ b/crates/arti-config/src/arti_defaults.toml @@ -11,10 +11,8 @@ socks_port = 9150 # Configure logging [logging] -# Enable logging to journald where available -journald = false - -# Specify filtering directives for tracing. +# Specify filtering directives for sending trace messages to the console +# (via standard output). # # It can be as simple as a single loglevel, or as complicated as a # list with per-module settings. @@ -25,7 +23,20 @@ journald = false # trace_filter = "info,tor_proto::channel=trace" # # For more information, see https://docs.rs/tracing-subscriber/0.2.20/tracing_subscriber/filter/struct.EnvFilter.html -trace_filter = "debug" +console = "debug" + +# As above, but specify filtering directives for sending trace messages to +# the journald logging system. +# +#journald = "" + +# You can also configure one or more log files, with different filters, and optional +# rotation. +# +#file = [ +# {path = "~/logs/debug.log", filter="debug"}, +# {path = "~/logs/trace.log", filter="trace", rotate="daily"}, +#] # Locations to use for storing things on disk. # diff --git a/crates/arti-config/src/lib.rs b/crates/arti-config/src/lib.rs index dee8964bf..3654a966f 100644 --- a/crates/arti-config/src/lib.rs +++ b/crates/arti-config/src/lib.rs @@ -45,8 +45,8 @@ mod options; pub use cmdline::CmdLine; pub use options::{ - ArtiConfig, ArtiConfigBuilder, LoggingConfig, LoggingConfigBuilder, ProxyConfig, - ProxyConfigBuilder, + ArtiConfig, ArtiConfigBuilder, LogRotation, LogfileConfig, LogfileConfigBuilder, LoggingConfig, + LoggingConfigBuilder, ProxyConfig, ProxyConfigBuilder, }; use tor_config::CfgPath; diff --git a/crates/arti-config/src/options.rs b/crates/arti-config/src/options.rs index 1202fbb31..346134f14 100644 --- a/crates/arti-config/src/options.rs +++ b/crates/arti-config/src/options.rs @@ -9,7 +9,7 @@ use arti_client::config::{ use derive_builder::Builder; use serde::Deserialize; use std::collections::HashMap; -use tor_config::ConfigBuildError; +use tor_config::{CfgPath, ConfigBuildError}; /// Default options to use for our configuration. pub(crate) const ARTI_DEFAULTS: &str = concat!(include_str!("./arti_defaults.toml"),); @@ -21,26 +21,32 @@ pub(crate) const ARTI_DEFAULTS: &str = concat!(include_str!("./arti_defaults.tom #[builder(build_fn(error = "ConfigBuildError"))] pub struct LoggingConfig { /// Filtering directives that determine tracing levels as described at - /// + /// /// /// You can override this setting with the -l, --log-level command line parameter. /// /// Example: "info,tor_proto::channel=trace" - // TODO(nickm) remove public elements when I revise this. - #[serde(default = "default_trace_filter")] - #[builder(default = "default_trace_filter()")] - pub trace_filter: String, + #[serde(default = "default_console_filter")] + #[builder(default = "default_console_filter()", setter(into, strip_option))] + console: Option, - /// Whether to log to journald - // TODO(nickm) remove public elements when I revise this. + /// Filtering directives for the journald logger. + /// + /// Only takes effect if Arti is built with the `journald` filter. + #[serde(default)] + #[builder(default, setter(into, strip_option))] + journald: Option, + + /// Configuration for one or more logfiles. #[serde(default)] #[builder(default)] - pub journald: bool, + file: Vec, } -/// Return a default value for `trace_filter`. -fn default_trace_filter() -> String { - "debug".to_owned() +/// Return a default tracing filter value for `logging.console`. +#[allow(clippy::unnecessary_wraps)] +fn default_console_filter() -> Option { + Some("debug".to_owned()) } impl Default for LoggingConfig { @@ -54,15 +60,93 @@ impl LoggingConfig { pub fn builder() -> LoggingConfigBuilder { LoggingConfigBuilder::default() } + + /// Return the configured journald filter, if one is present + pub fn journald_filter(&self) -> Option<&str> { + match self.journald { + Some(ref s) if !s.is_empty() => Some(s.as_str()), + _ => None, + } + } + + /// Return the configured stdout filter, if one is present + pub fn console_filter(&self) -> Option<&str> { + match self.console { + Some(ref s) if !s.is_empty() => Some(s.as_str()), + _ => None, + } + } + + /// Return a list of the configured log files + pub fn logfiles(&self) -> &[LogfileConfig] { + &self.file + } } impl From for LoggingConfigBuilder { fn from(cfg: LoggingConfig) -> LoggingConfigBuilder { let mut builder = LoggingConfigBuilder::default(); + if let Some(console) = cfg.console { + builder.console(console); + } + if let Some(journald) = cfg.journald { + builder.journald(journald); + } builder - .trace_filter(cfg.trace_filter) - .journald(cfg.journald); - builder + } +} + +/// Configuration information for an (optionally rotating) logfile. +#[derive(Deserialize, Debug, Builder, Clone, Eq, PartialEq)] +pub struct LogfileConfig { + /// How often to rotate the file? + #[serde(default)] + #[builder(default)] + rotate: LogRotation, + /// Where to write the files? + path: CfgPath, + /// Filter to apply before writing + filter: String, +} + +/// How often to rotate a log file +#[derive(Deserialize, Debug, Clone, Copy, Eq, PartialEq)] +#[non_exhaustive] +#[serde(rename_all = "lowercase")] +pub enum LogRotation { + /// Rotate logs daily + Daily, + /// Rotate logs hourly + Hourly, + /// Never rotate the log + Never, +} + +impl Default for LogRotation { + fn default() -> Self { + Self::Never + } +} + +impl LogfileConfig { + /// Return a new [`LogfileConfigBuilder`] + pub fn builder() -> LogfileConfigBuilder { + LogfileConfigBuilder::default() + } + + /// Return the configured rotation interval. + pub fn rotate(&self) -> LogRotation { + self.rotate + } + + /// Return the configured path to the log file. + pub fn path(&self) -> &CfgPath { + &self.path + } + + /// Return the configured filter. + pub fn filter(&self) -> &str { + &self.filter } } @@ -465,7 +549,7 @@ mod test { let mut bld = ArtiConfig::builder(); bld.proxy().socks_port(Some(9999)); - bld.logging().journald(true).trace_filter("warn".to_owned()); + bld.logging().console("warn"); bld.tor_network() .authorities(vec![auth]) .fallback_caches(vec![fallback]); diff --git a/crates/arti/Cargo.toml b/crates/arti/Cargo.toml index f8d5a84e8..f5c9188a9 100644 --- a/crates/arti/Cargo.toml +++ b/crates/arti/Cargo.toml @@ -35,6 +35,7 @@ tracing-subscriber = { version = "0.3.0", features = ["env-filter"] } tokio-crate = { package = "tokio", version = "1.4", optional = true, features = ["signal"] } clap = "2.33.0" tracing-journald = { version = "0.2.0", optional = true } +tracing-appender = "0.2.0" [target.'cfg(unix)'.dependencies] libc = { version = "0.2", default-features = false } diff --git a/crates/arti/src/main.rs b/crates/arti/src/main.rs index 76737835c..4df079e3f 100644 --- a/crates/arti/src/main.rs +++ b/crates/arti/src/main.rs @@ -202,7 +202,7 @@ fn main() -> Result<()> { let config: ArtiConfig = cfg.try_into()?; - trace::setup_logging(config.logging(), matches.value_of("loglevel")); + let _log_guards = trace::setup_logging(config.logging(), matches.value_of("loglevel"))?; if let Some(proxy_matches) = matches.subcommand_matches("proxy") { let socks_port = match ( diff --git a/crates/arti/src/trace.rs b/crates/arti/src/trace.rs index 3e529240d..4b728fdb0 100644 --- a/crates/arti/src/trace.rs +++ b/crates/arti/src/trace.rs @@ -1,46 +1,151 @@ //! Configure tracing subscribers for Arti -use arti_config::LoggingConfig; +use anyhow::{anyhow, Context, Result}; +use arti_config::{LogRotation, LogfileConfig, LoggingConfig}; +use std::path::Path; +use std::str::FromStr; +use tracing::Subscriber; +use tracing_appender::non_blocking::WorkerGuard; use tracing_subscriber::layer::SubscriberExt; use tracing_subscriber::prelude::*; -use tracing_subscriber::{fmt, registry, EnvFilter}; +use tracing_subscriber::{filter::Targets, fmt, registry, Layer}; -/// As [`EnvFilter::new`], but print a message if any directive in the -/// log is invalid. -fn filt_from_str_verbose(s: &str, source: &str) -> EnvFilter { - match EnvFilter::try_new(s) { - Ok(s) => s, - Err(_) => { - eprintln!("Problem in {}:", source); - EnvFilter::new(s) - } +/// As [`Targets::from_str`], but wrapped in an [`anyhow::Result`]. +// +// (Note that we have to use `Targets`, not `EnvFilter`: see comment in +// `setup_logging()`.) +fn filt_from_str_verbose(s: &str, source: &str) -> Result { + Targets::from_str(s).with_context(|| format!("in {}", source)) +} + +/// As filt_from_str_verbose, but treat an absent filter (or an empty string) as +/// None. +fn filt_from_opt_str(s: Option<&str>, source: &str) -> Result> { + s.map(|s| filt_from_str_verbose(s, source)).transpose() +} + +/// Try to construct a tracing [`Layer`] for logging to stdout. +fn console_layer(config: &LoggingConfig, cli: Option<&str>) -> Result> +where + S: Subscriber + for<'span> tracing_subscriber::registry::LookupSpan<'span>, +{ + let filter = cli + .map(|s| filt_from_str_verbose(s, "--log-level command line parameter")) + .or_else(|| filt_from_opt_str(config.console_filter(), "logging.console").transpose()) + .unwrap_or_else(|| Ok(Targets::from_str("debug").expect("bad default")))?; + Ok(fmt::Layer::default().with_filter(filter)) +} + +/// Try to construct a tracing [`Layer`] for logging to journald, if one is +/// configured. +#[cfg(feature = "journald")] +fn journald_layer(config: &LoggingConfig) -> Result> +where + S: Subscriber + for<'span> tracing_subscriber::registry::LookupSpan<'span>, +{ + if let Some(filter) = filt_from_opt_str(config.journald_filter(), "logging.journald")? { + Ok(Some(tracing_journald::layer()?.with_filter(filter))) + } else { + // Fortunately, Option implements Layer, so we can just return None here. + Ok(None) } } -/// Set up logging -pub(crate) fn setup_logging(config: &LoggingConfig, cli: Option<&str>) { - let env_filter = - match cli.map(|s| filt_from_str_verbose(s, "--log-level command line parameter")) { - Some(f) => f, - None => filt_from_str_verbose( - config.trace_filter.as_str(), - "trace_filter configuration option", - ), - }; +/// Try to construct a non-blocking tracing [`Layer`] for writing data to an +/// optionally rotating logfile. +/// +/// On success, return that layer, along with a WorkerGuard that needs to be +/// dropped when the program exits. +fn logfile_layer( + config: &LogfileConfig, +) -> Result<(impl Layer + Send + Sync + Sized, WorkerGuard)> +where + S: Subscriber + for<'span> tracing_subscriber::registry::LookupSpan<'span> + Send + Sync, +{ + use tracing_appender::{ + non_blocking, + rolling::{RollingFileAppender, Rotation}, + }; - let registry = registry().with(fmt::Layer::default()).with(env_filter); + let filter = filt_from_str_verbose(config.filter(), "logging.files.filter")?; + let rotation = match config.rotate() { + LogRotation::Daily => Rotation::DAILY, + LogRotation::Hourly => Rotation::HOURLY, + _ => Rotation::NEVER, + }; + let path = config.path().path()?; + let directory = path.parent().unwrap_or_else(|| Path::new(".")); + let fname = path + .file_name() + .ok_or_else(|| anyhow!("No path for log file")) + .map(Path::new)?; - if config.journald { - #[cfg(feature = "journald")] - if let Ok(journald) = tracing_journald::layer() { - registry.with(journald).init(); - return; - } - #[cfg(not(feature = "journald"))] - tracing::warn!( - "journald logging was selected, but arti was built without journald support." - ); + let appender = RollingFileAppender::new(rotation, directory, fname); + let (nonblocking, guard) = non_blocking(appender); + let layer = fmt::layer().with_writer(nonblocking).with_filter(filter); + Ok((layer, guard)) +} + +/// Try to construct a tracing [`Layer`] for all of the configured logfiles. +/// +/// On success, return that layer along with a list of [`WorkerGuard`]s that +/// need to be dropped when the program exits. +fn logfile_layers(config: &LoggingConfig) -> Result<(impl Layer, Vec)> +where + S: Subscriber + for<'span> tracing_subscriber::registry::LookupSpan<'span> + Send + Sync, +{ + let mut guards = Vec::new(); + if config.logfiles().is_empty() { + // As above, we have Option implements Layer, so we can return + // None in this case. + return Ok((None, guards)); } + let (layer, guard) = logfile_layer(&config.logfiles()[0])?; + guards.push(guard); + + // We have to use a dyn pointer here so we can build up linked list of + // arbitrary depth. + let mut layer: Box + Send + Sync + 'static> = Box::new(layer); + + for logfile in &config.logfiles()[1..] { + let (new_layer, guard) = logfile_layer(logfile)?; + layer = Box::new(layer.and_then(new_layer)); + guards.push(guard); + } + + Ok((Some(layer), guards)) +} + +/// Opaque structure that gets dropped only when the logs are no longer needed. +pub(crate) struct LogGuards { + /// The actual list of guards we're returning. + #[allow(unused)] + guards: Vec, +} + +/// Set up logging. +/// +/// Note that the returned LogGuard shouldn't be dropped while the program +/// is running; they're used to ensure that all the log files are cleaned up. +pub(crate) fn setup_logging(config: &LoggingConfig, cli: Option<&str>) -> Result { + // Important: We have to make sure that the individual layers we add here + // are not filters themselves. That means, for example, that we can't add + // an `EnvFilter` layer unless we want it to apply globally to _all_ layers. + // + // For a bit of discussion on the difference between per-layer filters and filters + // that apply to the entire registry, see + // https://docs.rs/tracing-subscriber/0.3.5/tracing_subscriber/layer/index.html#global-filtering + + let registry = registry().with(console_layer(config, cli)?); + + #[cfg(feature = "journald")] + let registry = registry.with(journald_layer(config)?); + + let (layer, guards) = logfile_layers(config)?; + let registry = registry.with(layer); + registry.init(); + + Ok(LogGuards { guards }) }