From b7cb8eebe751e0bfd6690df1dd9ee79cda7ae9d0 Mon Sep 17 00:00:00 2001 From: Antoni Przygienda Date: Sun, 23 Sep 2018 15:11:18 -0700 Subject: [PATCH 01/23] * fixed broken doc link --- README.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/README.md b/README.md index c73b46f..8ef1c8d 100644 --- a/README.md +++ b/README.md @@ -25,4 +25,4 @@ For more information, help, to report issues etc. see [slog-rs][slog-rs]. [slog-rs]: https://github.com/slog-rs/slog Documentation can be found on -[`slog-kvfilter` type](https://docs.rs/slog-kvfilter/*/slog-kvfilter/index.html). \ No newline at end of file +[`slog-kvfilter` type](https://docs.rs/slog-kvfilter/). \ No newline at end of file From 0f9771490b6c7a04bf3497fe6d1061d0024040fa Mon Sep 17 00:00:00 2001 From: Antoni Przygienda Date: Mon, 24 Sep 2018 09:09:53 -0700 Subject: [PATCH 02/23] * more permissive API that breaks 0.6.1 however --- Cargo.toml | 3 +-- src/lib.rs | 12 ++++++------ 2 files changed, 7 insertions(+), 8 deletions(-) diff --git a/Cargo.toml b/Cargo.toml index 9731ebc..7bf464b 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -1,6 +1,6 @@ [package] name = "slog-kvfilter" -version = "0.6.1" +version = "0.7.0" authors = ["Dawid Ciężarkiewicz ", "Tony Przygienda "] description = "Key values and Regex based filter Drain for slog-rs" keywords = ["slog", "logging", "log", "filter"] @@ -10,7 +10,6 @@ homepage = "https://github.com/slog-rs/slog" repository = "https://github.com/slog-rs/kvfilter" readme = "README.md" - [dependencies] slog = "2" regex = "1" diff --git a/src/lib.rs b/src/lib.rs index de175b8..f531e8d 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -149,14 +149,14 @@ impl<'a, D: slog::Drain> KVFilter { } /// only pass when this regex is found in the log message output. - pub fn only_pass_on_regex(mut self, regex: Regex) -> Self { - self.regex = Some(regex); + pub fn only_pass_on_regex(mut self, regex: Option) -> Self { + self.regex = regex; self } /// suppress output if this regex if found in the log message output. - pub fn always_suppress_on_regex(mut self, regex: Regex) -> Self { - self.neg_regex = Some(regex); + pub fn always_suppress_on_regex(mut self, regex: Option) -> Self { + self.neg_regex = regex; self } @@ -437,8 +437,8 @@ mod tests { // build some small filter let filter = KVFilter::new(drain.fuse(), Level::Info) - .only_pass_on_regex(Regex::new(r"PASS\d:").unwrap()) - .always_suppress_on_regex(Regex::new(r"NOPE\d:").unwrap()); + .only_pass_on_regex(Some(Regex::new(r"PASS\d:").unwrap())) + .always_suppress_on_regex(Some(Regex::new(r"NOPE\d:").unwrap())); // Get a root logger that will log into a given drain. let mainlog = Logger::root(filter.fuse(), o!("version" => env!("CARGO_PKG_VERSION"))); From f0376dc70c3414119936ff770d41f25fcff957e1 Mon Sep 17 00:00:00 2001 From: Tomas Dvorak Date: Thu, 27 Sep 2018 14:36:05 +0200 Subject: [PATCH 03/23] Complete rewrite to support arbitrary logic expressions --- src/lib.rs | 1058 +++++++++++++++++++++++++++++++++++----------------- 1 file changed, 725 insertions(+), 333 deletions(-) diff --git a/src/lib.rs b/src/lib.rs index de175b8..cff106c 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -1,8 +1,7 @@ -//! Filter records by matching some of their keys against a sets of values while allowing -//! for records of level high enough to pass. It also can apply a negative filter after the -//! positive filter to allow sophisticated 'hole-punching' into a matching category. Ultimately, -//! the resulting message (without keys and values) can be constrained by both presence of a regex -//! or its absence. +//! Filter records by matching their keys and values, and allows arbitrary +//! Bool logic expressions to be used. +//! +//! See the unit tests (especially `test_complex_example`) to see how to use it. #[cfg(test)] #[macro_use] @@ -11,446 +10,839 @@ extern crate slog; #[cfg(not(test))] extern crate slog; -extern crate regex; - -use std::collections::{HashMap, HashSet}; +use slog::{Drain, Key, Level, OwnedKVList, Record, Serializer, KV}; +use std::cell::Cell; use std::fmt; -use std::option::Option; -use std::panic::UnwindSafe; -use std::panic::RefUnwindSafe; -use std::fmt::format; - -use slog::KV; -use regex::Regex; - -// @todo: must that be thread-safe? -struct FilteringSerializer<'a> { - pending_matches: KVFilterListFlyWeight<'a>, - tmp_str: String, -} -impl<'a> slog::Serializer for FilteringSerializer<'a> { - fn emit_arguments(&mut self, key: slog::Key, val: &fmt::Arguments) -> slog::Result { - if self.pending_matches.is_empty() { - return Ok(()); - } +// ========== public KVFilter configuration - let matched = if let Some(keyvalues) = self.pending_matches.get(&key) { - self.tmp_str.clear(); - fmt::write(&mut self.tmp_str, *val)?; +// TODO #derive Serde deserialize - keyvalues.contains(&self.tmp_str) - } else { - false - }; +/// All the configuration for a KVFilter +#[derive(Clone, Debug, PartialEq)] +pub struct KVFilterConfig { + /// The specification of the filtering to be applied to the message. See the `FilterSpec` docs. + filter_spec: FilterSpec, + /// See the `EvaluationOrder` docs + evaluation_order: EvaluationOrder, +} + +/// Specification of a filter. Filters are either simple filters like "Some Key and value must match this:", +/// or compound filters like `And`, `Or` that are recursively composed from another filters. +/// +/// See the tests for examples. +#[derive(Clone, Debug, PartialEq)] +pub enum FilterSpec { + /// Always accept + Accept, + /// Always reject + Reject, + /// Accept when the key and value match the specification + MatchKV { key: String, value: String }, + /// Accept when logging level is at least given treshold. + /// + /// Example: message with level *Warning* will pass `FilterSpec::LevelAtLeast(Info)` + LevelAtLeast(Level), + /// Accept when all the sub-filters accept. Sub-filter are evaluated left-to-right. + /// + /// Please note that slog processes KV arguments to `log!` right to left, that is e. g. + /// `info!(log, "Msg"; "key1" => %value1, "key2" => %value2)` will first expand value2 and then value1. + And(Box, Box), + /// Accept when at least one of the sub-filters accepts. Sub-filter are evaluated left-to-right. + /// + /// Please note that slog processes KV arguments to `log!` right to left, that is e. g. + /// `info!(log, "Msg"; "key1" => %value1, "key2" => %value2)` will first expand value2 and then value1. + Or(Box, Box), + /// Turns an Accept into a Reject and vice versa. + Not(Box), +} - if matched { - self.pending_matches.remove(&key); +impl FilterSpec { + pub fn match_kv(key: impl ToString, value: impl ToString) -> FilterSpec { + FilterSpec::MatchKV { + key: key.to_string(), + value: value.to_string(), } + } - Ok(()) + pub fn and(self, other: FilterSpec) -> FilterSpec { + FilterSpec::And(Box::new(self), Box::new(other)) + } + + pub fn or(self, other: FilterSpec) -> FilterSpec { + FilterSpec::Or(Box::new(self), Box::new(other)) + } + + pub fn not(self) -> FilterSpec { + FilterSpec::Not(Box::new(self)) } } -/// Must be a hashmap since we do not rely on ordered keys -pub type KVFilterList = HashMap>; +/// Simple enum to express a message is to be either Accepted or Rejected +#[derive(Clone, Copy, Debug, PartialEq)] +pub enum AcceptOrReject { + Accept, + Reject, +} -/// flyweight copy that is created upfront and given to every serializer -type KVFilterListFlyWeight<'a> = HashMap<&'a str, &'a HashSet>; +/// The order of evaluation of message KVs and logger KVs +/// +/// The keys and values to be logged come from two sources: +/// +/// - some KVs are associated with the loggers, typically created with `new_log = log.new(o!("key": "value"))` +/// - some KVs are associated with the logged messages, e. g. `info!(log, "message"; "key" => "value")` +/// +/// Evaluation order allows us to specify, which KVs will be used for message filtering, and what order will be used. +/// +/// I presume in practice `LoggerOnly` and `LoggerAndMessage` will be the most commonly used orders. +/// +/// - `LoggerOnly` means that only KVs associated with the loggers will be used for message filtering +/// - `LoggerAndMessage` means that first KVs associated with the loggers will be used for message filtering. +/// If the filter isn't determined by the loggers KVs, message KVs will be used. +/// +/// This can have both performance and semantics implications. If you are curious, +/// see the comment at `KVFilter` for a more thorough discussion. +/// +#[derive(Clone, Debug, PartialEq)] +pub enum EvaluationOrder { + LoggerOnly, + MessageOnly, + LoggerAndMessage, + MessageAndLogger, +} -/// `Drain` filtering records using list of keys and values they -/// must have unless they are of a higher level than filtering applied. -/// it can apply a negative filter as well that overrides any matches but -/// will let higher level than filtering applied as well. +/// The KVFilter itself. It implements `Drain`. +/// +/// It passes messages matching the criteria specified by a given `config` into an underlying `drain` +/// and discards the rest. +/// --- +/// The rest of this documentation is a little bit difficult, both for me as a writer and for the reader. +/// I try to explain what happens under the hood when a message is being processed, and what performance +/// implications it may have. +/// +/// ## TL;DR: I try hard not to do any unnecessary work within the limits set by slog implementation. +/// +/// ## Long version: /// -/// This `Drain` filters a log entry on a filtermap -/// that holds the key name in question and acceptable values -/// Key values are gathered up the whole hierarchy of inherited -/// loggers. +/// When a log message is to be processed, we obtain two KV sets from two sources: /// -/// Example -/// ======= +/// - KVs associated with the loggers, typically created with `new_log = log.new(o!("key": "value"))` +/// - KVs associated with the logged messages, e. g. `info!(log, "message"; "key" => "value")` /// -/// Logger( ... ; o!("thread" => "100"); -/// log( ... ; "packet" => "send"); -/// log( ... ; "packet" => "receive"); +/// Each of the sets can be evaluated independently. Each KV set is evaluated in two stages: /// -/// can be filtered on a map containing "thread" key component. If the -/// values contain "100" the log will be output, otherwise filtered. -/// The filtering map can contain further key "packet" and value "send". -/// With that the output for "receive" would be filtered. +/// ### 1. `kv_set.serialize(filtering_serializer)` is called for each KV set /// -/// More precisely +/// This will eventually make `EvaluateFilterSerializer::emit_arguments` +/// called for each Key and Value in the KV set. +/// The important thing is that if there are any closures (`FnValue` and friends), +/// **all** of the closures in the KV set will be called at this step. +/// That means that if e. g. you don't need to filter on message KVs, just logger KVs +/// is enough for you, you can save a some CPU by using `EvaluationOrder::LoggerOnly`. That will +/// prevent the message closures from being called when a particular message is rejected based on logger KVs. +/// Also, if you use e. g. `EvaluationOrder::LoggerAndMessage` and a particular message is resolved +/// to be `Reject`-ed or `Accept`-ed early by just looking at the logger KV set, the message KV set will not +/// be `serialize()`d because the result is already known. /// -/// * a key is ignored until present in `filters`, otherwise an entry must -/// match for all the keys present in `filters` for any of the values given -/// for the key to pass the filter. -/// * an entry that hits any value of any negative filter key is filtered, this -/// takes precedence over `filters` -/// * Behavior of empty `KVFilterList` is undefined but normally anything should pass. -/// * Behavior of `KVFilter` that has same key in both the matching and the suppressing -/// section is undefined even if we have different values there. Logically, it should -/// be matching the positive and pass and only suppress negative if it finds matching -/// value but it's untested. +/// ### 2. `EvaluateFilterSerializer::emit_arguments(key: String, value: std::fmt::Arguments)` gets called for each KV /// -/// Additionally, the resulting message (without keys and values) can be constrained -/// by both presence of a regex or its absence by applying the `only_pass_on_regex` -/// and `always_suppress_on_regex` API calls. As the names suggest, suppression wins -/// if both regex's are set. +/// The `value` parameter is not a String, but a ` std::fmt::Arguments` +/// that needs to be turned into a String first so we can compare it to filters specified in the config. /// -/// Usage -/// ===== +/// We do two optimizations here: /// -/// Filtering in large systems that consist of multiple threads of same -/// code or have functionality of interest spread across many components, -/// modules, such as e.g. "sending packet" or "running FSM". -pub struct KVFilter { +/// a. Reuse the same String for expanding all the values to avoid some allocation +/// +/// b. Only expand the value when we are not sure about the result yet. Again, if we don't need the value, because +/// we already know a message will be Rejected or Accepted, we don't expand the value at all. Remember from +/// bullet 1. that `kv_set.serialize(filtering_serializer)` will call `emit_arguments` with **all** the KVs from a +/// particular set, so we try hard not do any unnecessary work with them when not needed. +pub struct KVFilter { drain: D, - filters: Option, - neg_filters: Option, - level: slog::Level, - regex: Option, - neg_regex: Option, + config: KVFilterConfig, } -impl UnwindSafe for KVFilter {} -impl RefUnwindSafe for KVFilter {} +impl KVFilter { + pub fn new_from_config(drain: D, config: KVFilterConfig) -> Self { + KVFilter { drain, config } + } -impl<'a, D: slog::Drain> KVFilter { - /// Create `KVFilter` letting e'thing pass unless filters are set. Anything more - /// important than `level` will pass in any case. - /// - /// * `drain` - drain to be sent to - /// * `level` - maximum level filtered, higher levels pass by without filtering - pub fn new(drain: D, level: slog::Level) -> Self { + pub fn new(drain: D, filter_spec: FilterSpec, evaluation_order: EvaluationOrder) -> Self { KVFilter { - drain: drain, - level: level, - filters: None, - neg_filters: None, - regex: None, - neg_regex: None, + drain, + config: KVFilterConfig { + filter_spec, + evaluation_order, + }, } } - /// pass through entries with all keys with _any_ of the matching values in its entries - /// or ignore condition if None - pub fn only_pass_any_on_all_keys(mut self, filters: Option) -> Self { - self.filters = filters; - self - } - - /// suppress _any_ key with _any_ of the matching values in its entries or ignore - /// condition if None. - /// @note: This takes precedence over `only_pass_any` - pub fn always_suppress_any(mut self, filters: Option) -> Self { - self.neg_filters = filters; - self - } - - /// only pass when this regex is found in the log message output. - pub fn only_pass_on_regex(mut self, regex: Regex) -> Self { - self.regex = Some(regex); - self - } - - /// suppress output if this regex if found in the log message output. - pub fn always_suppress_on_regex(mut self, regex: Regex) -> Self { - self.neg_regex = Some(regex); - self - } - - fn is_match(&self, record: &slog::Record, logger_values: &slog::OwnedKVList) -> bool { - // Can't use chaining here, as it's not possible to cast - // SyncSerialize to Serialize - let mut ser = FilteringSerializer { - pending_matches: self.filters.as_ref().map_or(HashMap::new(), |f| { - f.iter().map(|(k, v)| (k.as_str(), v)).collect() - }), - tmp_str: String::new(), + fn is_match(&self, record: &Record, logger_values: &OwnedKVList) -> bool { + let mut evaluating_serializer = EvaluateFilterSerializer { + filter: Filter::from_spec(&self.config.filter_spec), + message_level: record.level(), + tmp_string: String::new(), }; - let mut negser = FilteringSerializer { - pending_matches: self.neg_filters.as_ref().map_or(HashMap::new(), |ref f| { - f.iter().map(|(k, v)| (k.as_str(), v)).collect() - }), - tmp_str: String::new(), - }; - - record.kv().serialize(record, &mut ser).unwrap(); - - // negative we have to go all way down to check for _any_ key match - record.kv().serialize(record, &mut negser).unwrap(); - logger_values.serialize(record, &mut negser).unwrap(); + macro_rules! serialize_and_return_if_decided { + ($kv: expr) => { + $kv + .serialize(record, &mut evaluating_serializer) + .unwrap(); // Is unwrap the right thing to do here? - let anynegativematch = || - negser.pending_matches.len() == self.neg_filters.as_ref() - .map_or(0, - |m| m.keys().len()); - - let mut pass = if ser.pending_matches.is_empty() { - // if e'thing matched on the positive make sure _nothing_ matched on negative - anynegativematch() - } else { - // check inside whether we find more matches - logger_values.serialize(record, &mut ser).unwrap(); - - if ser.pending_matches.is_empty() { - anynegativematch() - } else { - false + match evaluating_serializer.filter { + Filter::Accept => return true, + Filter::Reject => return false, + _ => {} + } } - }; - - if pass && (self.regex.is_some() || self.neg_regex.is_some()) { - let res = format(*record.msg()); + } - if let Some(ref posmatch) = self.regex { - pass = posmatch.is_match(&res); - }; + match self.config.evaluation_order { + EvaluationOrder::LoggerOnly => { + serialize_and_return_if_decided!(logger_values); + } + EvaluationOrder::MessageOnly => { + serialize_and_return_if_decided!(record.kv()); + } + EvaluationOrder::LoggerAndMessage => { + serialize_and_return_if_decided!(logger_values); + serialize_and_return_if_decided!(record.kv()); + } + EvaluationOrder::MessageAndLogger => { + serialize_and_return_if_decided!(record.kv()); + serialize_and_return_if_decided!(logger_values); + } + } - if pass { - if let Some(ref negmatch) = self.neg_regex { - pass = !negmatch.is_match(&res); + fn final_evaluate_filter(filter: &mut Filter, level: Level) -> AcceptOrReject { + match filter { + Filter::Accept => AcceptOrReject::Accept, + Filter::Reject => AcceptOrReject::Reject, + Filter::LevelAtLeast(treshold) => { + if level.is_at_least(*treshold) { + AcceptOrReject::Accept + } else { + AcceptOrReject::Reject + } + } + Filter::MatchKV { .. } => AcceptOrReject::Reject, + Filter::And(a, b) => { + if final_evaluate_filter(a, level) == AcceptOrReject::Accept + && final_evaluate_filter(b, level) == AcceptOrReject::Accept + { + AcceptOrReject::Accept + } else { + AcceptOrReject::Reject + } + } + Filter::Or(a, b) => { + if final_evaluate_filter(a, level) == AcceptOrReject::Accept + || final_evaluate_filter(b, level) == AcceptOrReject::Accept + { + AcceptOrReject::Accept + } else { + AcceptOrReject::Reject + } + } + Filter::Not(f) => { + if final_evaluate_filter(f, level) == AcceptOrReject::Accept { + AcceptOrReject::Reject + } else { + AcceptOrReject::Accept + } } } } - pass + let final_result = final_evaluate_filter(&mut evaluating_serializer.filter, record.level()); + + match final_result { + AcceptOrReject::Accept => true, + AcceptOrReject::Reject => false, + } } } -impl<'a, D: slog::Drain> slog::Drain for KVFilter { - type Err = D::Err; +impl Drain for KVFilter +where + D: Drain, +{ type Ok = Option; + type Err = Option; fn log( &self, - info: &slog::Record, + record: &slog::Record, logger_values: &slog::OwnedKVList, ) -> Result { - // println!("{:#?}", info.msg()); - - if info.level() < self.level || self.is_match(info, logger_values) { - self.drain.log(info, logger_values).map(Some) + if self.is_match(record, logger_values) { + self.drain + .log(record, logger_values) + .map(Some) + .map_err(Some) } else { Ok(None) } } } +// ========== Implementation + +/// An actual filter in progress that get's progressively simplified during a log message evaluation. +/// A lightweight clone of FilterSpec. +#[derive(Debug, PartialEq)] +enum Filter<'a> { + Accept, + Reject, + MatchKV { key: &'a str, value: &'a str }, + LevelAtLeast(Level), + And(Box>, Box>), + Or(Box>, Box>), + Not(Box>), +} + +impl<'a> Filter<'a> { + fn from_spec<'b: 'a>(spec: &'b FilterSpec) -> Filter<'a> { + match spec { + FilterSpec::Accept => Filter::Accept, + FilterSpec::Reject => Filter::Reject, + FilterSpec::MatchKV { key, value } => Filter::MatchKV { + key: &key, + value: &value, + }, + FilterSpec::LevelAtLeast(level) => Filter::LevelAtLeast(*level), + FilterSpec::And(a, b) => Filter::And( + Box::new(Filter::from_spec(&a)), + Box::new(Filter::from_spec(&b)), + ), + FilterSpec::Or(a, b) => Filter::Or( + Box::new(Filter::from_spec(&a)), + Box::new(Filter::from_spec(&b)), + ), + FilterSpec::Not(f) => Filter::Not(Box::new(Filter::from_spec(&f))), + } + } +} + +/// Helper struct to turn arguments into a string and cache it. +/// The actual cached string is passed around as `tmp_string` to +/// the `is_equal` method. That is quite ugly, but I just didn't succeed adding a +/// tmp_string: &'a mut String +/// member to this struct and successfully negotiate its usage with the borrow checker. +struct ArgumentsValueMemo<'a> { + arguments: &'a fmt::Arguments<'a>, + is_serialized: Cell, +} + +impl<'a> ArgumentsValueMemo<'a> { + fn is_equal(&self, value: &str, tmp_string: &mut String) -> Result { + if !self.is_serialized.get() { + tmp_string.clear(); + fmt::write(tmp_string, *self.arguments)?; + self.is_serialized.set(true); + } + Ok(tmp_string == value) + } +} + +/// This is the filtering workhorse. It used to process a single log message. +/// It is set up with the logging level of the log message and a filter. +/// `tmp_str` is there just to avoid repeated string allocation and serves as +/// a temporary serialized string for `ArgumentsValueMemo` +struct EvaluateFilterSerializer<'a> { + message_level: Level, + filter: Filter<'a>, + tmp_string: String, +} + +impl<'a> Serializer for EvaluateFilterSerializer<'a> { + fn emit_arguments(&mut self, key: Key, value: &fmt::Arguments) -> slog::Result { + let mut value = ArgumentsValueMemo { + arguments: value, + is_serialized: Cell::new(false), + }; + + /// (Partially) in-place evaluate the filter for a particular key and value + fn evaluate_filter_with_kv( + filter: &mut Filter, + level: Level, + key: Key, + value: &mut ArgumentsValueMemo, + tmp_string: &mut String, + ) -> slog::Result { + let maybe_simplified_filter = match filter { + Filter::Accept => None, + Filter::Reject => None, + Filter::LevelAtLeast(treshold) => { + if level.is_at_least(*treshold) { + Some(Filter::Accept) + } else { + Some(Filter::Reject) + } + } + Filter::MatchKV { + key: this_key, + value: this_value, + } => { + if &key == this_key { + if value.is_equal(this_value, tmp_string)? { + Some(Filter::Accept) + } else { + None + } + } else { + None + } + } + Filter::And(a, b) => { + evaluate_filter_with_kv(a, level, key, value, tmp_string)?; + if **a == Filter::Reject { + Some(Filter::Reject) + } else { + evaluate_filter_with_kv(b, level, key, value, tmp_string)?; + if **a == Filter::Accept { + if **b == Filter::Accept { + Some(Filter::Accept) + } else if **b == Filter::Reject { + Some(Filter::Reject) + } else { + None + } + } else { + None + } + } + } + Filter::Or(a, b) => { + evaluate_filter_with_kv(a, level, key, value, tmp_string)?; + if **a == Filter::Accept { + Some(Filter::Accept) + } else { + evaluate_filter_with_kv(b, level, key, value, tmp_string)?; + if **b == Filter::Accept { + Some(Filter::Accept) + } else if **a == Filter::Reject && **b == Filter::Reject { + Some(Filter::Reject) + } else { + None + } + } + } + Filter::Not(f) => { + evaluate_filter_with_kv(f, level, key, value, tmp_string)?; + if **f == Filter::Accept { + Some(Filter::Reject) + } else if **f == Filter::Reject { + Some(Filter::Accept) + } else { + None + } + } + }; + + if let Some(simplified_filter) = maybe_simplified_filter { + *filter = simplified_filter + } + + Ok(()) + } + + evaluate_filter_with_kv( + &mut self.filter, + self.message_level, + key, + &mut value, + &mut self.tmp_string, + )?; + + Ok(()) + } +} + #[cfg(test)] mod tests { - use super::KVFilter; - use slog::{Drain, Level, Logger, OwnedKVList, Record}; - use regex::Regex; - use std::collections::HashSet; - use std::iter::FromIterator; - use std::sync::Mutex; - use std::fmt::Display; - use std::fmt::Formatter; - use std::fmt::Result as FmtResult; + use super::FilterSpec::*; + use super::*; + + use std::fmt; use std::io; - use std::sync::Arc; + use std::sync::atomic::{AtomicUsize, Ordering}; + use std::sync::{Arc, Mutex}; - const YES: &'static str = "YES"; - const NO: &'static str = "NO"; + use slog::{Drain, FnValue, Level, Logger, OwnedKVList, Record}; #[derive(Debug)] struct StringDrain { output: Arc>>, } - /// seriously hacked logger drain that just counts messages to make - /// sure we have tests behaving correcly impl<'a> Drain for StringDrain { - type Err = io::Error; type Ok = (); + type Err = io::Error; - fn log(&self, info: &Record, _: &OwnedKVList) -> io::Result<()> { - let mut lo = self.output.lock().unwrap(); - let fmt = format!("{:?}", info.msg()); - - if !fmt.contains(YES) && !fmt.contains(NO) { - panic!(fmt); + fn log(&self, message: &Record, _: &OwnedKVList) -> io::Result<()> { + let formatted = format!("{:?}", message.msg()); + if !formatted.contains("ACCEPT") && !formatted.contains("REJECT") { + panic!(formatted); } - (*lo).push(fmt); + self.output.lock().unwrap().push(formatted); Ok(()) } } - impl<'a> Display for StringDrain { - fn fmt(&self, f: &mut Formatter) -> FmtResult { - write!(f, "none") + impl<'a> fmt::Display for StringDrain { + fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result { + write!(f, "String drain: {:#?}", self.output.lock().unwrap()) } } - fn testkvfilter(d: D) -> KVFilter { - KVFilter::new(d, Level::Info).only_pass_any_on_all_keys(Some( - vec![ - ( - "thread".to_string(), - HashSet::from_iter(vec!["100".to_string(), "200".to_string()]), - ), - ( - "direction".to_string(), - HashSet::from_iter(vec!["send".to_string(), "receive".to_string()]), - ), - ].into_iter() - .collect(), - )) + /// A message that adds the message into the formatted_messages Vec as a side-effect of debug format + struct TestingMessage { + message: String, + increment_on_format: Arc, + } + + impl TestingMessage { + fn new(message: &str, increment_on_format: &Arc) -> Self { + TestingMessage { + message: message.to_owned(), + increment_on_format: Arc::clone(increment_on_format), + } + } } - fn testnegkvfilter(f: KVFilter) -> KVFilter { - f.always_suppress_any(Some( - vec![ - ( - "deepcomp".to_string(), - HashSet::from_iter(vec!["1".to_string(), "2".to_string()]), - ), - ( - "deepercomp".to_string(), - HashSet::from_iter(vec!["4".to_string(), "5".to_string()]), - ), - ].into_iter() - .collect(), - )) + impl fmt::Debug for TestingMessage { + fn fmt(&self, f: &mut fmt::Formatter) -> Result<(), fmt::Error> { + self.increment_on_format.fetch_add(1, Ordering::Relaxed); + write!(f, "{}", self.message) + } } - #[test] - /// get an asserting Drain, get a couple of loggers that - /// have different nodes, components and see whether filtering - /// is applied properly on the derived `Logger` copies - fn nodecomponentlogfilter() { - assert!(Level::Critical < Level::Warning); + struct Tester { + accepted_messages: Arc>>, + evaluated_log_values: Arc, + log: Logger, + } - let out = Arc::new(Mutex::new(vec![])); + impl Tester { + fn new(filter_spec: FilterSpec, evaluation_order: EvaluationOrder) -> Self { + let accepted_messages = Arc::new(Mutex::new(Vec::new())); + let evaluated_log_values = Arc::new(AtomicUsize::new(0)); + let evaluated_log_values_clone = Arc::clone(&evaluated_log_values); + let drain = StringDrain { + output: accepted_messages.clone(), + }; + let filter = KVFilter::new(drain, filter_spec, evaluation_order); + let log = Logger::root( + filter.fuse(), + o!("main_log" => FnValue(move |_: &Record| { + evaluated_log_values_clone.fetch_add(1, Ordering::Relaxed); + "m" + })), + ); + + Tester { + accepted_messages, + evaluated_log_values, + log, + } + } + + fn assert_accepted(&self, expected_count: usize) { + let accepted_messages = self.accepted_messages.lock().unwrap(); + for message in accepted_messages.iter() { + assert!( + message.contains("ACCEPT"), + "Message without ACCEPT accepted: `{}`", + message + ) + } + let actual_count = accepted_messages.len(); + assert_eq!(expected_count, actual_count) + } + + fn assert_evaluated_log_values(&self, expected_count: usize) { + let actual_count = self.evaluated_log_values.load(Ordering::Relaxed); + assert_eq!(expected_count, actual_count) + } + } - let drain = StringDrain { - output: out.clone(), + #[test] + fn test_lazy_format() { + let filter_spec = FilterSpec::match_kv("sub_log_key", "sub_log_value") + .or(FilterSpec::match_kv("key1", "value1")) + .or(FilterSpec::match_kv("key2", "value2")); + + let tester = Tester::new(filter_spec, EvaluationOrder::LoggerAndMessage); + + let value1_evaluations = Arc::new(AtomicUsize::new(0)); + let value1 = TestingMessage::new("value1", &value1_evaluations); + let value2_evaluations = Arc::new(AtomicUsize::new(0)); + let value2 = TestingMessage::new("value2", &value2_evaluations); + let invalid_value_evaluations = Arc::new(AtomicUsize::new(0)); + let invalid_value = TestingMessage::new("invalid", &invalid_value_evaluations); + + let assert_evaluations = |value1: usize, value2: usize, invalid: usize| { + assert_eq!(value1, value1_evaluations.load(Ordering::Relaxed)); + value1_evaluations.store(0, Ordering::Relaxed); + assert_eq!(value2, value2_evaluations.load(Ordering::Relaxed)); + value2_evaluations.store(0, Ordering::Relaxed); + assert_eq!(invalid, invalid_value_evaluations.load(Ordering::Relaxed)); + invalid_value_evaluations.store(0, Ordering::Relaxed); }; - // build some small filter - let filter = testkvfilter(drain); + let sub_log = tester.log.new(o!("sub_log_key" => "sub_log_value")); + info!(sub_log, "ACCEPT because of sub_log_key"; "key1" => ?value1); + assert_evaluations(0, 0, 0); - // Get a root logger that will log into a given drain. - let mainlog = Logger::root(filter.fuse(), o!("version" => env!("CARGO_PKG_VERSION"))); - let sublog = mainlog.new(o!("thread" => "200", "sub" => "sub")); - let subsublog = sublog.new(o!("direction" => "send")); - let subsubsublog = subsublog.new(o!()); + info!(tester.log, "ACCEPT because of key1"; "key1" => ?value1); + assert_evaluations(1, 0, 0); - let wrongthread = mainlog.new(o!("thread" => "400", "sub" => "sub")); + info!(tester.log, "ACCEPT because of key1"; "key1" => ?value1); + assert_evaluations(1, 0, 0); - info!(mainlog, "NO: filtered, main, no keys"); - info!(mainlog, "YES: unfiltered, on of thread matches, direction matches"; - "thread" => "100", "direction" => "send"); - info!(mainlog, - "YES: unfiltered, on of thread matches, direction matches, different key order"; - "direction" => "send", "thread" => "100"); + info!(tester.log, "ACCEPT because of key2"; "key2" => ?value2); + assert_evaluations(0, 1, 0); - warn!(mainlog, "YES: unfiltered, higher level"); // level high enough to pass anyway + // Slog processes KVs in reverse order. If this ever changes, please update the relevant documentation for FilterSpec. + info!(tester.log, + "ACCEPT because of key1, don't process key2."; + "key2" => ?invalid_value, "key1" => ?value1 + ); + assert_evaluations(1, 0, 0); - debug!(mainlog, "NO: filtered, level to low, no keys"); // level low + info!(tester.log, + "ACCEPT because of key2, key1 had to be processed first with negative result."; + "key2" => ?value2, "key1" => ?invalid_value + ); + assert_evaluations(0, 1, 1); - info!(mainlog, "NO: filtered, wrong thread on record"; - "thread" => "300", "direction" => "send"); + info!(tester.log, "REJECT"; "key2" => ?invalid_value, "key1" => ?invalid_value ); + assert_evaluations(0, 0, 2); - info!(wrongthread, "NO: filtered, wrong thread on sublog"); + tester.assert_evaluated_log_values(7); + tester.assert_accepted(6); + } - info!(sublog, "NO: filtered sublog, missing dirction "); + #[test] + fn test_evaluation_order() { + fn new_tester(evaluation_order: EvaluationOrder) -> Tester { + Tester::new( + FilterSpec::match_kv("key", "value").or(FilterSpec::match_kv("sub_log", "a")), + evaluation_order, + ) + } - info!(sublog, "YES: unfiltered sublog with added directoin"; - "direction" => "receive"); + { + let tester = new_tester(EvaluationOrder::LoggerOnly); + let sub_log = tester.log.new(o!("sub_log" => "a")); - info!( - subsubsublog, - "YES: unfiltered subsubsublog, direction on subsublog, thread on sublog" - ); + info!(sub_log, "ACCEPT: Will be accepted because of sub log"); + tester.assert_accepted(1); + info!(tester.log, "REJECT: Won't be accepted because message KVs are not evaluated"; "key" => "value"); + tester.assert_accepted(1); + tester.assert_evaluated_log_values(2); + } - // test twice same keyword with right value will give filter match - let stackedthreadslog = wrongthread.new(o!("thread" => "200")); + { + let tester = new_tester(EvaluationOrder::MessageOnly); + let sub_log = tester.log.new(o!("sub_log" => "a")); + + info!( + sub_log, + "REJECT: Will be rejected because log KVs are ignored" + ); + tester.assert_accepted(0); + info!(tester.log, "ACCEPT"; "key" => "value"); + tester.assert_accepted(1); + tester.assert_evaluated_log_values(0); + } - info!(stackedthreadslog, - "YES: unfiltered since one of the threads matches from inherited"; - "direction" => "send"); + { + let tester = new_tester(EvaluationOrder::LoggerAndMessage); + let sub_log = tester.log.new(o!("sub_log" => "a")); - println!("resulting output: {:#?}", *out.lock().unwrap()); + info!(tester.log, "ACCEPT"; "key" => "value"); + info!(sub_log, "ACCEPT: Will be accepted because of sub log"); + tester.assert_accepted(2); + tester.assert_evaluated_log_values(2); + } - assert_eq!(out.lock().unwrap().len(), 6); + { + let tester = new_tester(EvaluationOrder::MessageAndLogger); + let sub_log = tester.log.new(o!("sub_log" => "a")); + + info!(tester.log, "ACCEPT"; "key" => "value"); + info!(sub_log, "ACCEPT: Will be accepted because of sub log"); + tester.assert_accepted(2); + tester.assert_evaluated_log_values(1); + } } #[test] - /// get an asserting Drain, get a couple of loggers that - /// have different nodes, components and deep/deeper components and see whether filtering - /// is applied properly on the derived `Logger` copies while punching holes for the disallowed - /// values - fn negnodecomponentlogfilter() { - assert!(Level::Critical < Level::Warning); - - let out = Arc::new(Mutex::new(vec![])); - - let drain = StringDrain { - output: out.clone(), - }; + fn test_sub_log() { + { + let tester = Tester::new( + FilterSpec::match_kv("main_log", "m"), + EvaluationOrder::LoggerAndMessage, + ); + let sub_log = tester.log.new(o!("sub_log" => "a")); + let sub_sub_log = sub_log.new(o!("sub_sub_log" => "b")); + + info!(tester.log, "ACCEPT: main log"); + info!(sub_log, "ACCEPT: sub log inherits the main_log KV"); + info!(sub_sub_log, "ACCEPT: the same for sub sub log"); + tester.assert_accepted(3); + } - // build some small filter - let filter = testnegkvfilter(testkvfilter(drain.fuse())); - - // Get a root logger that will log into a given drain. - let mainlog = Logger::root(filter.fuse(), o!("version" => env!("CARGO_PKG_VERSION"))); - let sublog = mainlog.new(o!("thread" => "200", "sub" => "sub")); - let subsublog = sublog.new(o!("direction" => "send")); - // deep match won't match - let subsubsublog = subsublog.new(o!("deepcomp" => "0")); - // deep match will filter - let negsubsubsublog = subsublog.new(o!("deepcomp" => "1")); - - info!(mainlog, "NO: filtered, main, no keys"); - info!(mainlog, "YES: unfiltered, on of thread matches, direction matches"; - "thread" => "100", "direction" => "send"); - info!(subsubsublog, "YES: unfiltered, on of thread matches, direction matches, deep doesn't apply"; - "thread" => "100", "direction" => "send"); - info!(negsubsubsublog, "NO: filtered, on of thread matches, direction matches, deep negative applies"; - "thread" => "100", "direction" => "send"); - info!(subsubsublog, "NO: filtered, on of thread matches, direction matches, deep doesn't apply but deeper does"; - "thread" => "100", "direction" => "send", "deepercomp" => "4"); - info!(subsubsublog, "YES: unfiltered, on of thread matches, direction matches, deep doesn't apply and deeper doesn't"; - "thread" => "100", "direction" => "send", "deepercomp" => "7"); - - println!("resulting output: {:#?}", *out.lock().unwrap()); - - assert_eq!(out.lock().unwrap().len(), 3); + { + let tester = Tester::new( + FilterSpec::match_kv("sub_sub_log", "b"), + EvaluationOrder::LoggerAndMessage, + ); + let sub_log = tester.log.new(o!("sub_log" => "a")); + let sub_sub_log = sub_log.new(o!("sub_sub_log" => "b")); + + info!( + tester.log, + "REJECT: main log doesn't have the sub_sub_log key" + ); + info!(sub_log, "REJECT: neither has the sub_log"); + info!(sub_sub_log, "ACCEPT: sub sub log has it"); + tester.assert_accepted(1); + } } #[test] - /// test negative and positive - fn regextest() { - assert!(Level::Critical < Level::Warning); + fn test_accept() { + let tester = Tester::new(Accept, EvaluationOrder::LoggerAndMessage); + info!(tester.log, "ACCEPT: Everything will pass"); + warn!(tester.log, "ACCEPT: Everything will pass"); + tester.assert_accepted(2); + } - let out = Arc::new(Mutex::new(vec![])); + #[test] + fn test_reject() { + let tester = Tester::new(Reject, EvaluationOrder::LoggerAndMessage); + info!(tester.log, "REJECT: Everything will be rejected"); + warn!(tester.log, "REJECT: Everything will be rejected"); + tester.assert_accepted(0); + } - let drain = StringDrain { - output: out.clone(), - }; + #[test] + fn test_level_at_least() { + let tester = Tester::new( + LevelAtLeast(Level::Warning), + EvaluationOrder::LoggerAndMessage, + ); + info!(tester.log, "REJECT: Level too low"); + warn!(tester.log, "ACCEPT: Level good"); + error!(tester.log, "ACCEPT: Level good"); + tester.assert_accepted(2); + } - // build some small filter - let filter = KVFilter::new(drain.fuse(), Level::Info) - .only_pass_on_regex(Regex::new(r"PASS\d:").unwrap()) - .always_suppress_on_regex(Regex::new(r"NOPE\d:").unwrap()); + #[test] + fn test_match_kv() { + let tester = Tester::new( + FilterSpec::match_kv("key", "value"), + EvaluationOrder::LoggerAndMessage, + ); + info!(tester.log, "ACCEPT: Good key"; "key" => "value"); + info!(tester.log, "REJECT"; "main_log" => "m"); + info!(tester.log, "REJECT"; "key" => "bad_value"); + info!(tester.log, "REJECT"; "bad_key" => "value"); + tester.assert_accepted(1); + } - // Get a root logger that will log into a given drain. - let mainlog = Logger::root(filter.fuse(), o!("version" => env!("CARGO_PKG_VERSION"))); + #[test] + fn test_and() { + { + let tester = Tester::new( + FilterSpec::match_kv("key1", "value1").and(FilterSpec::match_kv("key2", "value2")), + EvaluationOrder::LoggerAndMessage, + ); + info!(tester.log, "ACCEPT"; "key1" => "value1", "key2" => "value2"); + info!(tester.log, "REJECT: key1"; "key1" => "value1"); + info!(tester.log, "REJECT: key1"; "key1" => "value1", "key2" => "boo"); + info!(tester.log, "REJECT: key2"; "key2" => "value2"); + info!(tester.log, "REJECT: key2"; "key1" => "boo", "key2" => "value2"); + info!(tester.log, "REJECT"; "key1" => "boo", "key2" => "boo"); + tester.assert_accepted(1); + } + } - info!(mainlog, "NO: filtered, no positive"); - info!(mainlog, "NO: NOPE2 PASS0 filtered, negative"); - info!(mainlog, "NO: filtered, no positive"); - info!(mainlog, "YES: PASS2: not filtered, positive"); - info!(mainlog, "YES: {}: not filtered, positive", "PASS4"); + #[test] + fn test_or() { + { + let tester = Tester::new( + FilterSpec::match_kv("key1", "value1").or(FilterSpec::match_kv("key2", "value2")), + EvaluationOrder::LoggerAndMessage, + ); + info!(tester.log, "ACCEPT: key1"; "key1" => "value1"); + info!(tester.log, "ACCEPT: key1"; "key1" => "value1", "key2" => "boo"); + info!(tester.log, "ACCEPT: key2"; "key2" => "value2"); + info!(tester.log, "ACCEPT: key2"; "key1" => "boo", "key2" => "value2"); + info!(tester.log, "REJECT"; "key1" => "boo", "key2" => "boo"); + tester.assert_accepted(4); + } + } - println!("resulting output: {:#?}", *out.lock().unwrap()); + #[test] + fn test_not() { + { + let tester = Tester::new( + FilterSpec::match_kv("key1", "value1").not(), + EvaluationOrder::LoggerAndMessage, + ); + info!(tester.log, "REJECT: key1 match was turned into negative"; "key1" => "value1"); + info!(tester.log, "ACCEPT: No match, we turn it into a negative, that is Accept"; "key1" => "boo"); + tester.assert_accepted(1); + } + } - assert_eq!(out.lock().unwrap().len(), 2); + #[test] + fn test_complex_example() { + // This is an example that mimics the original KVFilter. + // We express the following example filter: + // KVFilter { + // filters: key1 -> [value1a, value1b], key2 -> [value2] + // neg_filters: neg_key1 -> [neg_value1], neg_key2 -> [neg_value2a, neg_value2b] + // level: Debug (that actually means level at least Info) + // } + + let match_kv = FilterSpec::match_kv; + + // (key1 must be either value1a or value1b) AND key2 must be value2 + let positive_filter = (match_kv("key1", "value1a").or(match_kv("key1", "value1b"))) + .and(match_kv("key2", "value2")); + + // neg_key1 must be neg_value1 OR neg_key2 must be neg_value2a OR neg_key2 must be neg_value2b + let negative_filter = match_kv("neg_key1", "neg_value1") + .or(match_kv("neg_key2", "neg_value2a")) + .or(match_kv("neg_key2", "neg_value2b")); + + // We pass everything with level at least info, OR anything that matches the positive filter but not the negative one. + let filter = + FilterSpec::LevelAtLeast(Level::Info).or(positive_filter.and(negative_filter.not())); + + let tester = Tester::new(filter, EvaluationOrder::LoggerAndMessage); + + info!(tester.log, "ACCEPT: Info level"); + debug!(tester.log, "REJECT 1: Level too low"); + debug!(tester.log, "ACCEPT"; "key1" => "value1a", "key2" => "value2"); + debug!(tester.log, "ACCEPT"; "key1" => "value1b", "key2" => "value2"); + debug!(tester.log, "REJECT 2"; "key1" => "invalid", "key2" => "value2"); + debug!(tester.log, "REJECT 3"; "key1" => "value1b", "key2" => "invalid"); + debug!(tester.log, "REJECT 4"; "invalid" => "value1b", "key2" => "value2"); + debug!(tester.log, "REJECT 5"; "invalid" => "value1b", "key2" => "value2"); + debug!(tester.log, "REJECT 6"; "key1" => "value1a", "key2" => "value2", "neg_key1" => "neg_value1"); + debug!(tester.log, "REJECT 7"; "key1" => "value1a", "key2" => "value2", "neg_key2" => "neg_value2b"); + debug!(tester.log, "ACCEPT"; "key1" => "value1a", "key2" => "value2", "neg_key1" => "invalid"); + + tester.assert_accepted(4); } } + From 74d19eba401ef077651526ec749b3ed00f11b020 Mon Sep 17 00:00:00 2001 From: Tomas Dvorak Date: Thu, 27 Sep 2018 18:38:26 +0200 Subject: [PATCH 04/23] Added another showcase: test_complex_example_2() --- src/lib.rs | 58 ++++++++++++++++++++++++++++++++++++++++++++++-------- 1 file changed, 50 insertions(+), 8 deletions(-) diff --git a/src/lib.rs b/src/lib.rs index cff106c..1f67e13 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -230,18 +230,18 @@ impl KVFilter { Filter::And(a, b) => { if final_evaluate_filter(a, level) == AcceptOrReject::Accept && final_evaluate_filter(b, level) == AcceptOrReject::Accept - { - AcceptOrReject::Accept - } else { + { + AcceptOrReject::Accept + } else { AcceptOrReject::Reject } } Filter::Or(a, b) => { if final_evaluate_filter(a, level) == AcceptOrReject::Accept || final_evaluate_filter(b, level) == AcceptOrReject::Accept - { - AcceptOrReject::Accept - } else { + { + AcceptOrReject::Accept + } else { AcceptOrReject::Reject } } @@ -265,8 +265,8 @@ impl KVFilter { } impl Drain for KVFilter -where - D: Drain, + where + D: Drain, { type Ok = Option; type Err = Option; @@ -844,5 +844,47 @@ mod tests { tester.assert_accepted(4); } + + #[test] + fn test_complex_example_2() { + // This is an example that implements the behavior requested at this issue: + // https://github.com/sile/sloggers/issues/9#issuecomment-422685244 + // + // The requested behavior: + // + // 1. pass all records with ("subsystem": "A1" || "subsystem": "A2") && level at least debug + // 2. pass all records with (subsystem": "B1" || "subsystem": "B2") && level at least info + // 3. pass all records with level at least warn + // 4. reject all other records + + let match_kv = FilterSpec::match_kv; + + let subsystem_a = (match_kv("subsystem", "A1").or(match_kv("subsystem", "A2"))) + .and(FilterSpec::LevelAtLeast(Level::Debug)); + let subsystem_b = (match_kv("subsystem", "B1").or(match_kv("subsystem", "B2"))) + .and(FilterSpec::LevelAtLeast(Level::Info)); + let filter = subsystem_a.or(subsystem_b).or(FilterSpec::LevelAtLeast(Level::Warning)); + + let tester = Tester::new(filter, EvaluationOrder::LoggerAndMessage); + + // Rule 1 + debug!(tester.log, "ACCEPT"; "subsystem" => "A1"); + debug!(tester.log, "ACCEPT"; "subsystem" => "A2"); + debug!(tester.log, "REJECT trace XXX"; "subsystem" => "XXX"); + + // Rule 2 + debug!(tester.log, "REJECT"; "subsystem" => "B1"); + info!(tester.log, "ACCEPT"; "subsystem" => "B1"); + info!(tester.log, "ACCEPT"; "subsystem" => "B2"); + info!(tester.log, "REJECT debug XXX"; "subsystem" => "XXX"); + + // Rule 3 + warn!(tester.log, "ACCEPT: Info level"); + + // Rule 4 + info!(tester.log, "REJECT: Level too low"); + + tester.assert_accepted(5); + } } From 8578bedb046184c6b7f044a3b48f15669d760b95 Mon Sep 17 00:00:00 2001 From: Tomas Dvorak Date: Thu, 27 Sep 2018 18:39:12 +0200 Subject: [PATCH 05/23] Added .idea to .gitignore --- .gitignore | 1 + 1 file changed, 1 insertion(+) diff --git a/.gitignore b/.gitignore index 4691d50..291a950 100644 --- a/.gitignore +++ b/.gitignore @@ -1,5 +1,6 @@ /target /.cargo +/.idea Cargo.lock tags rusty-tags.vi From 0d9782b6bdc031457d26b2e88e49cac617be6fff Mon Sep 17 00:00:00 2001 From: Tomas Dvorak Date: Thu, 27 Sep 2018 18:54:10 +0200 Subject: [PATCH 06/23] (optional) Serde serialize/deserialize support of the filter configuration --- Cargo.toml | 3 +++ src/lib.rs | 64 +++++++++++++++++++++++++++++++++++++----------------- 2 files changed, 47 insertions(+), 20 deletions(-) diff --git a/Cargo.toml b/Cargo.toml index 9731ebc..4acc0ad 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -10,7 +10,10 @@ homepage = "https://github.com/slog-rs/slog" repository = "https://github.com/slog-rs/kvfilter" readme = "README.md" +[features] +default=["serde"] [dependencies] +serde = { version = "1", optional = true, features = ["derive"] } slog = "2" regex = "1" diff --git a/src/lib.rs b/src/lib.rs index 1f67e13..0271c17 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -1,7 +1,12 @@ //! Filter records by matching their keys and values, and allows arbitrary //! Bool logic expressions to be used. //! -//! See the unit tests (especially `test_complex_example`) to see how to use it. +//! See the unit tests (especially `test_complex_example` and `test_complex_example_2`) to see how to use it. +//! + +#[cfg(feature = "serde")] +#[macro_use] +extern crate serde; #[cfg(test)] #[macro_use] @@ -16,9 +21,10 @@ use std::fmt; // ========== public KVFilter configuration -// TODO #derive Serde deserialize - /// All the configuration for a KVFilter +/// +/// If compiled with the "serde" feature, the config can be serialized and deserialized using Serde. +#[cfg_attr(feature = "serde", derive(Serialize, Deserialize))] #[derive(Clone, Debug, PartialEq)] pub struct KVFilterConfig { /// The specification of the filtering to be applied to the message. See the `FilterSpec` docs. @@ -27,10 +33,25 @@ pub struct KVFilterConfig { evaluation_order: EvaluationOrder, } +// https://serde.rs/remote-derive.html +#[derive(Serialize, Deserialize)] +#[serde(remote = "Level")] +pub enum LevelSerdeDef { + Critical, + Error, + Warning, + Info, + Debug, + Trace, +} + /// Specification of a filter. Filters are either simple filters like "Some Key and value must match this:", /// or compound filters like `And`, `Or` that are recursively composed from another filters. /// +/// If compiled with the "serde" feature, the config can be serialized and deserialized using Serde. +/// /// See the tests for examples. +#[cfg_attr(feature = "serde", derive(Serialize, Deserialize))] #[derive(Clone, Debug, PartialEq)] pub enum FilterSpec { /// Always accept @@ -42,6 +63,7 @@ pub enum FilterSpec { /// Accept when logging level is at least given treshold. /// /// Example: message with level *Warning* will pass `FilterSpec::LevelAtLeast(Info)` + #[serde(with = "LevelSerdeDef")] LevelAtLeast(Level), /// Accept when all the sub-filters accept. Sub-filter are evaluated left-to-right. /// @@ -78,13 +100,6 @@ impl FilterSpec { } } -/// Simple enum to express a message is to be either Accepted or Rejected -#[derive(Clone, Copy, Debug, PartialEq)] -pub enum AcceptOrReject { - Accept, - Reject, -} - /// The order of evaluation of message KVs and logger KVs /// /// The keys and values to be logged come from two sources: @@ -103,6 +118,7 @@ pub enum AcceptOrReject { /// This can have both performance and semantics implications. If you are curious, /// see the comment at `KVFilter` for a more thorough discussion. /// +#[cfg_attr(feature = "serde", derive(Serialize, Deserialize))] #[derive(Clone, Debug, PartialEq)] pub enum EvaluationOrder { LoggerOnly, @@ -230,18 +246,18 @@ impl KVFilter { Filter::And(a, b) => { if final_evaluate_filter(a, level) == AcceptOrReject::Accept && final_evaluate_filter(b, level) == AcceptOrReject::Accept - { - AcceptOrReject::Accept - } else { + { + AcceptOrReject::Accept + } else { AcceptOrReject::Reject } } Filter::Or(a, b) => { if final_evaluate_filter(a, level) == AcceptOrReject::Accept || final_evaluate_filter(b, level) == AcceptOrReject::Accept - { - AcceptOrReject::Accept - } else { + { + AcceptOrReject::Accept + } else { AcceptOrReject::Reject } } @@ -265,8 +281,8 @@ impl KVFilter { } impl Drain for KVFilter - where - D: Drain, +where + D: Drain, { type Ok = Option; type Err = Option; @@ -289,6 +305,13 @@ impl Drain for KVFilter // ========== Implementation +/// Simple enum to express a message is to be either Accepted or Rejected +#[derive(Clone, Copy, Debug, PartialEq)] +enum AcceptOrReject { + Accept, + Reject, +} + /// An actual filter in progress that get's progressively simplified during a log message evaluation. /// A lightweight clone of FilterSpec. #[derive(Debug, PartialEq)] @@ -863,7 +886,9 @@ mod tests { .and(FilterSpec::LevelAtLeast(Level::Debug)); let subsystem_b = (match_kv("subsystem", "B1").or(match_kv("subsystem", "B2"))) .and(FilterSpec::LevelAtLeast(Level::Info)); - let filter = subsystem_a.or(subsystem_b).or(FilterSpec::LevelAtLeast(Level::Warning)); + let filter = subsystem_a + .or(subsystem_b) + .or(FilterSpec::LevelAtLeast(Level::Warning)); let tester = Tester::new(filter, EvaluationOrder::LoggerAndMessage); @@ -887,4 +912,3 @@ mod tests { tester.assert_accepted(5); } } - From 4e8ed157600c6b24db339e534c6dcbaa2f4fe437 Mon Sep 17 00:00:00 2001 From: Tomas Dvorak Date: Thu, 27 Sep 2018 19:19:18 +0200 Subject: [PATCH 07/23] Improved the test_complex_example_2 test case --- src/lib.rs | 27 ++++++++++++++++++--------- 1 file changed, 18 insertions(+), 9 deletions(-) diff --git a/src/lib.rs b/src/lib.rs index 0271c17..d6f9749 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -36,7 +36,7 @@ pub struct KVFilterConfig { // https://serde.rs/remote-derive.html #[derive(Serialize, Deserialize)] #[serde(remote = "Level")] -pub enum LevelSerdeDef { +enum LevelSerdeDef { Critical, Error, Warning, @@ -879,6 +879,8 @@ mod tests { // 2. pass all records with (subsystem": "B1" || "subsystem": "B2") && level at least info // 3. pass all records with level at least warn // 4. reject all other records + // In all cases, make decisions based only on the LOGGER keys and values, + // don't take the message KVs into account let match_kv = FilterSpec::match_kv; @@ -890,18 +892,25 @@ mod tests { .or(subsystem_b) .or(FilterSpec::LevelAtLeast(Level::Warning)); - let tester = Tester::new(filter, EvaluationOrder::LoggerAndMessage); + // EvaluationOrder::Logger means that only the logger KVs will be used for message filtering + let tester = Tester::new(filter, EvaluationOrder::Logger); + let subsystem_a1 = tester.log.new(o!("subsystem" => "A1")); + let subsystem_a2 = tester.log.new(o!("subsystem" => "A2")); + let subsystem_b1 = tester.log.new(o!("subsystem" => "B1")); + let subsystem_b2 = tester.log.new(o!("subsystem" => "B2")); + let subsystem_xxx = tester.log.new(o!("subsystem" => "XXX")); // Rule 1 - debug!(tester.log, "ACCEPT"; "subsystem" => "A1"); - debug!(tester.log, "ACCEPT"; "subsystem" => "A2"); - debug!(tester.log, "REJECT trace XXX"; "subsystem" => "XXX"); + debug!(subsystem_a1, "ACCEPT"); + debug!(subsystem_a2, "ACCEPT"); + debug!(subsystem_xxx, "REJECT debug XXX"); + debug!(subsystem_xxx, "REJECT debug XXX, message KV is discarded"; "subsystem" => "A1"); // Rule 2 - debug!(tester.log, "REJECT"; "subsystem" => "B1"); - info!(tester.log, "ACCEPT"; "subsystem" => "B1"); - info!(tester.log, "ACCEPT"; "subsystem" => "B2"); - info!(tester.log, "REJECT debug XXX"; "subsystem" => "XXX"); + debug!(subsystem_b1, "REJECT"); + info!(subsystem_b1, "ACCEPT"); + info!(subsystem_b2, "ACCEPT"); + info!(subsystem_xxx, "REJECT info XXX"); // Rule 3 warn!(tester.log, "ACCEPT: Info level"); From 334911c0d0718e488cd358f8954bc46a65517070 Mon Sep 17 00:00:00 2001 From: Tomas Dvorak Date: Thu, 27 Sep 2018 21:22:26 +0200 Subject: [PATCH 08/23] Added the FilterSpec::any_of and FilterSpec::all_of utility methods --- src/lib.rs | 77 +++++++++++++++++++++++++++++++++++++++++++++--------- 1 file changed, 65 insertions(+), 12 deletions(-) diff --git a/src/lib.rs b/src/lib.rs index d6f9749..f770609 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -91,6 +91,38 @@ impl FilterSpec { FilterSpec::And(Box::new(self), Box::new(other)) } + /// Creates a filter that accepts if any of the variant accepts. Rejects on empty `variants` collection. + /// + /// variants are composed using foldr, that is [a, b, c] -> Or(a, Or(b, c)) + pub fn any_of(variants: &[FilterSpec]) -> FilterSpec { + match variants.split_first() { + Some((head, tail)) => { + if tail.is_empty() { + head.clone() + } else { + head.clone().or(Self::any_of(tail)) + } + } + None => FilterSpec::Reject + } + } + + /// Creates a filter that accepts if all of the variants accept. Rejects on empty `variants` collection. + /// + /// variants are composed using foldr, that is [a, b, c] -> And(a, And(b, c)) + pub fn all_of(variants: &[FilterSpec]) -> FilterSpec { + match variants.split_first() { + Some((head, tail)) => { + if tail.is_empty() { + head.clone() + } else { + head.clone().and(Self::all_of(tail)) + } + } + None => FilterSpec::Reject + } + } + pub fn or(self, other: FilterSpec) -> FilterSpec { FilterSpec::Or(Box::new(self), Box::new(other)) } @@ -246,18 +278,18 @@ impl KVFilter { Filter::And(a, b) => { if final_evaluate_filter(a, level) == AcceptOrReject::Accept && final_evaluate_filter(b, level) == AcceptOrReject::Accept - { - AcceptOrReject::Accept - } else { + { + AcceptOrReject::Accept + } else { AcceptOrReject::Reject } } Filter::Or(a, b) => { if final_evaluate_filter(a, level) == AcceptOrReject::Accept || final_evaluate_filter(b, level) == AcceptOrReject::Accept - { - AcceptOrReject::Accept - } else { + { + AcceptOrReject::Accept + } else { AcceptOrReject::Reject } } @@ -281,8 +313,8 @@ impl KVFilter { } impl Drain for KVFilter -where - D: Drain, + where + D: Drain, { type Ok = Option; type Err = Option; @@ -593,6 +625,21 @@ mod tests { } } + #[test] + fn test_any_all_of() { + let a = FilterSpec::match_kv("k1", "v1"); + let b = FilterSpec::match_kv("k2", "v2"); + let c = FilterSpec::match_kv("k3", "v3"); + assert_eq!( + a.clone().or(b.clone().or(c.clone())), + FilterSpec::any_of(&[a.clone(), b.clone(), c.clone()]) + ); + assert_eq!( + a.clone().and(b.clone().and(c.clone())), + FilterSpec::all_of(&[a.clone(), b.clone(), c.clone()]) + ); + } + #[test] fn test_lazy_format() { let filter_spec = FilterSpec::match_kv("sub_log_key", "sub_log_value") @@ -848,6 +895,8 @@ mod tests { .or(match_kv("neg_key2", "neg_value2b")); // We pass everything with level at least info, OR anything that matches the positive filter but not the negative one. + // `And` and `Or` rules are evaluated first-to-last, so put the simplest rules (`LevelAtLeast`) first so the filter + // doesn't have to evaluate the more complicated rules if the simpler one already decides a message's fate let filter = FilterSpec::LevelAtLeast(Level::Info).or(positive_filter.and(negative_filter.not())); @@ -886,14 +935,18 @@ mod tests { let subsystem_a = (match_kv("subsystem", "A1").or(match_kv("subsystem", "A2"))) .and(FilterSpec::LevelAtLeast(Level::Debug)); + let subsystem_b = (match_kv("subsystem", "B1").or(match_kv("subsystem", "B2"))) .and(FilterSpec::LevelAtLeast(Level::Info)); - let filter = subsystem_a - .or(subsystem_b) - .or(FilterSpec::LevelAtLeast(Level::Warning)); + + // `And` and `Or` rules are evaluated first-to-last, so put the simplest rules (`LevelAtLeast`) first so the filter + // doesn't have to evaluate the more complicated rules if the simpler one already decides a message's fate + let filter = FilterSpec::LevelAtLeast(Level::Warning) + .or(subsystem_a) + .or(subsystem_b); // EvaluationOrder::Logger means that only the logger KVs will be used for message filtering - let tester = Tester::new(filter, EvaluationOrder::Logger); + let tester = Tester::new(filter, EvaluationOrder::LoggerOnly); let subsystem_a1 = tester.log.new(o!("subsystem" => "A1")); let subsystem_a2 = tester.log.new(o!("subsystem" => "A2")); let subsystem_b1 = tester.log.new(o!("subsystem" => "B1")); From 78a82891e617bfd101156d09489afe49fc059fd1 Mon Sep 17 00:00:00 2001 From: Tomas Dvorak Date: Fri, 28 Sep 2018 13:05:51 +0200 Subject: [PATCH 09/23] impl Default for EvaluationOrder --- src/lib.rs | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/src/lib.rs b/src/lib.rs index f770609..ce16e75 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -159,6 +159,12 @@ pub enum EvaluationOrder { MessageAndLogger, } +impl Default for EvaluationOrder { + fn default() -> Self { + EvaluationOrder::LoggerAndMessage + } +} + /// The KVFilter itself. It implements `Drain`. /// /// It passes messages matching the criteria specified by a given `config` into an underlying `drain` From 351fb14259d1c5ae7d7b337257f60eb7c2e3cc33 Mon Sep 17 00:00:00 2001 From: Tomas Dvorak Date: Fri, 28 Sep 2018 13:17:36 +0200 Subject: [PATCH 10/23] make KVFilterConfig fields public --- src/lib.rs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/lib.rs b/src/lib.rs index ce16e75..718b78b 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -28,9 +28,9 @@ use std::fmt; #[derive(Clone, Debug, PartialEq)] pub struct KVFilterConfig { /// The specification of the filtering to be applied to the message. See the `FilterSpec` docs. - filter_spec: FilterSpec, + pub filter_spec: FilterSpec, /// See the `EvaluationOrder` docs - evaluation_order: EvaluationOrder, + pub evaluation_order: EvaluationOrder, } // https://serde.rs/remote-derive.html From 7a1f21329b305c7c4015f68ecf2ee5a284c3c579 Mon Sep 17 00:00:00 2001 From: Tomas Dvorak Date: Fri, 28 Sep 2018 13:18:46 +0200 Subject: [PATCH 11/23] #derive Copy for EvaluationOrder --- src/lib.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/lib.rs b/src/lib.rs index 718b78b..c6b3bf1 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -151,7 +151,7 @@ impl FilterSpec { /// see the comment at `KVFilter` for a more thorough discussion. /// #[cfg_attr(feature = "serde", derive(Serialize, Deserialize))] -#[derive(Clone, Debug, PartialEq)] +#[derive(Copy, Clone, Debug, PartialEq)] pub enum EvaluationOrder { LoggerOnly, MessageOnly, From 6a67097765961a165714303a750bb27e0e0e422e Mon Sep 17 00:00:00 2001 From: Tomas Dvorak Date: Fri, 5 Oct 2018 16:37:58 +0200 Subject: [PATCH 12/23] Implemented FilterSpec::MatchAllValues --- src/lib.rs | 109 ++++++++++++++++++++++++++++++++++++++++++++++------- 1 file changed, 95 insertions(+), 14 deletions(-) diff --git a/src/lib.rs b/src/lib.rs index c6b3bf1..233fead 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -17,6 +17,7 @@ extern crate slog; use slog::{Drain, Key, Level, OwnedKVList, Record, Serializer, KV}; use std::cell::Cell; +use std::collections::HashSet; use std::fmt; // ========== public KVFilter configuration @@ -58,13 +59,22 @@ pub enum FilterSpec { Accept, /// Always reject Reject, - /// Accept when the key and value match the specification - MatchKV { key: String, value: String }, /// Accept when logging level is at least given treshold. /// /// Example: message with level *Warning* will pass `FilterSpec::LevelAtLeast(Info)` #[serde(with = "LevelSerdeDef")] LevelAtLeast(Level), + /// Accept when the key and value match the specification + MatchKV { key: String, value: String }, + /// Accept when all `values` for a given `key` are present. + /// + /// Equivalent to `MatchKV {key, value1}.and(MatchKV {key, value2}).and(...)`, + /// but is implemented using a `HashSet` instead of a linked `And` structure, so + /// it will be more performant for a larger number of values + /// (no benchmarks done, but my guess is > 3 values). + /// + /// Always accepts on empty `values` + MatchAllValues { key: String, values: Vec }, /// Accept when all the sub-filters accept. Sub-filter are evaluated left-to-right. /// /// Please note that slog processes KV arguments to `log!` right to left, that is e. g. @@ -87,6 +97,13 @@ impl FilterSpec { } } + pub fn match_all_values(key: impl ToString, values: &[impl ToString]) -> FilterSpec { + FilterSpec::MatchAllValues { + key: key.to_string(), + values: values.iter().map(|v| v.to_string()).collect(), + } + } + pub fn and(self, other: FilterSpec) -> FilterSpec { FilterSpec::And(Box::new(self), Box::new(other)) } @@ -103,7 +120,7 @@ impl FilterSpec { head.clone().or(Self::any_of(tail)) } } - None => FilterSpec::Reject + None => FilterSpec::Reject, } } @@ -119,7 +136,7 @@ impl FilterSpec { head.clone().and(Self::all_of(tail)) } } - None => FilterSpec::Reject + None => FilterSpec::Reject, } } @@ -281,21 +298,28 @@ impl KVFilter { } } Filter::MatchKV { .. } => AcceptOrReject::Reject, + Filter::MatchAllValues { values, .. } => { + if values.is_empty() { + AcceptOrReject::Accept + } else { + AcceptOrReject::Reject + } + } Filter::And(a, b) => { if final_evaluate_filter(a, level) == AcceptOrReject::Accept && final_evaluate_filter(b, level) == AcceptOrReject::Accept - { - AcceptOrReject::Accept - } else { + { + AcceptOrReject::Accept + } else { AcceptOrReject::Reject } } Filter::Or(a, b) => { if final_evaluate_filter(a, level) == AcceptOrReject::Accept || final_evaluate_filter(b, level) == AcceptOrReject::Accept - { - AcceptOrReject::Accept - } else { + { + AcceptOrReject::Accept + } else { AcceptOrReject::Reject } } @@ -319,8 +343,8 @@ impl KVFilter { } impl Drain for KVFilter - where - D: Drain, +where + D: Drain, { type Ok = Option; type Err = Option; @@ -346,8 +370,8 @@ impl Drain for KVFilter /// Simple enum to express a message is to be either Accepted or Rejected #[derive(Clone, Copy, Debug, PartialEq)] enum AcceptOrReject { - Accept, Reject, + Accept, } /// An actual filter in progress that get's progressively simplified during a log message evaluation. @@ -356,7 +380,14 @@ enum AcceptOrReject { enum Filter<'a> { Accept, Reject, - MatchKV { key: &'a str, value: &'a str }, + MatchKV { + key: &'a str, + value: &'a str, + }, + MatchAllValues { + key: &'a str, + values: HashSet<&'a str>, + }, LevelAtLeast(Level), And(Box>, Box>), Or(Box>, Box>), @@ -372,6 +403,10 @@ impl<'a> Filter<'a> { key: &key, value: &value, }, + FilterSpec::MatchAllValues { key, values } => Filter::MatchAllValues { + key: &key, + values: values.iter().map(|v| v.as_str()).collect(), + }, FilterSpec::LevelAtLeast(level) => Filter::LevelAtLeast(*level), FilterSpec::And(a, b) => Filter::And( Box::new(Filter::from_spec(&a)), @@ -405,6 +440,20 @@ impl<'a> ArgumentsValueMemo<'a> { } Ok(tmp_string == value) } + + fn remove_from_hash_set( + &self, + set: &mut HashSet<&str>, + tmp_string: &mut String, + ) -> Result<(), fmt::Error> { + if !self.is_serialized.get() { + tmp_string.clear(); + fmt::write(tmp_string, *self.arguments)?; + self.is_serialized.set(true); + } + set.remove(tmp_string.as_str()); + Ok(()) + } } /// This is the filtering workhorse. It used to process a single log message. @@ -456,6 +505,21 @@ impl<'a> Serializer for EvaluateFilterSerializer<'a> { None } } + Filter::MatchAllValues { + key: this_key, + values, + } => { + if &key == this_key { + value.remove_from_hash_set(values, tmp_string)?; + if values.is_empty() { + Some(Filter::Accept) + } else { + None + } + } else { + None + } + } Filter::And(a, b) => { evaluate_filter_with_kv(a, level, key, value, tmp_string)?; if **a == Filter::Reject { @@ -833,6 +897,23 @@ mod tests { tester.assert_accepted(1); } + #[test] + fn test_match_all_values() { + let tester = Tester::new( + FilterSpec::match_all_values("key", &["v1", "v2", "v3"]), + EvaluationOrder::LoggerAndMessage, + ); + info!(tester.log, "ACCEPT"; "key" => "v1", "key" => "v2", "key" => "v3"); + info!(tester.log, "ACCEPT"; "key" => "v3", "key" => "v3", "key" => "v1", "key" => "v2"); + info!(tester.log, "ACCEPT"; "key" => "v3", "key" => "v5", "key" => "v1", "key" => "v2"); + info!(tester.log, "ACCEPT"; "key" => "v3", "key" => "v1", "key" => "v2", "key" => "v5",); + info!(tester.log, "REJECT"); + info!(tester.log, "REJECT"; "key" => "v2", "key" => "v3"); + info!(tester.log, "REJECT"; "key" => "v1", "key" => "v3"); + info!(tester.log, "REJECT"; "key" => "v1", "key" => "v5", "key" => "v3"); + tester.assert_accepted(4); + } + #[test] fn test_and() { { From 94b03ace2fe4c9d1b991654fc71e36e88e2e547f Mon Sep 17 00:00:00 2001 From: Tomas Dvorak Date: Fri, 5 Oct 2018 16:43:59 +0200 Subject: [PATCH 13/23] Fixed compilation when serde feature is disabled --- src/lib.rs | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/src/lib.rs b/src/lib.rs index 233fead..55318f6 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -35,8 +35,9 @@ pub struct KVFilterConfig { } // https://serde.rs/remote-derive.html -#[derive(Serialize, Deserialize)] -#[serde(remote = "Level")] +#[cfg_attr(feature = "serde", derive(Serialize, Deserialize))] +#[cfg_attr(feature = "serde", serde(remote = "Level"))] +#[allow(dead_code)] enum LevelSerdeDef { Critical, Error, @@ -62,7 +63,7 @@ pub enum FilterSpec { /// Accept when logging level is at least given treshold. /// /// Example: message with level *Warning* will pass `FilterSpec::LevelAtLeast(Info)` - #[serde(with = "LevelSerdeDef")] + #[cfg_attr(feature = "serde", serde(with = "LevelSerdeDef"))] LevelAtLeast(Level), /// Accept when the key and value match the specification MatchKV { key: String, value: String }, From 22332a2edf006068bd7a30e1544d5defc6e43c9e Mon Sep 17 00:00:00 2001 From: Tomas Dvorak Date: Fri, 5 Oct 2018 20:38:38 +0200 Subject: [PATCH 14/23] Implemented FilterSpec::MatchMsgRegex, some refactoring --- Cargo.toml | 5 +- src/lib.rs | 156 ++++++++++++++++++++++++++++++++++++++++------------- 2 files changed, 124 insertions(+), 37 deletions(-) diff --git a/Cargo.toml b/Cargo.toml index 4acc0ad..23a3692 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -11,9 +11,12 @@ repository = "https://github.com/slog-rs/kvfilter" readme = "README.md" [features] -default=["serde"] +# serde_regex should be enabled iff serde is enabled. +# I don't know how to express this in Cargo.toml automatically, though. +default=["serde", "serde_regex"] [dependencies] serde = { version = "1", optional = true, features = ["derive"] } +serde_regex = { version = "0", optional = true } slog = "2" regex = "1" diff --git a/src/lib.rs b/src/lib.rs index 55318f6..455613d 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -7,6 +7,8 @@ #[cfg(feature = "serde")] #[macro_use] extern crate serde; +#[cfg(feature = "serde")] +extern crate serde_regex; #[cfg(test)] #[macro_use] @@ -14,11 +16,15 @@ extern crate slog; #[cfg(not(test))] extern crate slog; +extern crate regex; -use slog::{Drain, Key, Level, OwnedKVList, Record, Serializer, KV}; use std::cell::Cell; use std::collections::HashSet; use std::fmt; +use std::panic::{RefUnwindSafe, UnwindSafe}; + +use regex::Regex; +use slog::{Drain, Key, Level, OwnedKVList, Record, Serializer, KV}; // ========== public KVFilter configuration @@ -47,6 +53,31 @@ enum LevelSerdeDef { Trace, } + +/// Just a wrapper around Regex to provide +/// +/// - Serde support +/// - PartialEq (compares the original Regex strings, not the regular expression semantics) +/// - `impl UnwindSafe` - the wrapped Regex is not UnwindSafe, we mark RegexWrapper as being so. +#[cfg_attr(feature = "serde", derive(Serialize, Deserialize))] +#[derive(Clone, Debug)] +pub struct RegexWrapper( + #[cfg_attr(feature = "serde", serde(with = "serde_regex"))] + Regex +); + +// Just cargo-culting here. I'm not sure what are the actual implications of Regex +// not being Unwind-safe :-( +impl UnwindSafe for RegexWrapper {} + +impl RefUnwindSafe for RegexWrapper {} + +impl PartialEq for RegexWrapper { + fn eq(&self, other: &RegexWrapper) -> bool { + format!("{}", self.0) == format!("{}", other.0) + } +} + /// Specification of a filter. Filters are either simple filters like "Some Key and value must match this:", /// or compound filters like `And`, `Or` that are recursively composed from another filters. /// @@ -76,6 +107,8 @@ pub enum FilterSpec { /// /// Always accepts on empty `values` MatchAllValues { key: String, values: Vec }, + /// Accept when the log message matches the given regular expression. + MatchMsgRegex(RegexWrapper), /// Accept when all the sub-filters accept. Sub-filter are evaluated left-to-right. /// /// Please note that slog processes KV arguments to `log!` right to left, that is e. g. @@ -105,6 +138,14 @@ impl FilterSpec { } } + pub fn match_msg_regex(regex: Regex) -> FilterSpec { + FilterSpec::MatchMsgRegex(RegexWrapper(regex)) + } + + pub fn try_match_msg_regex(regex: &str) -> Result { + Ok(Self::match_msg_regex(Regex::new(regex)?)) + } + pub fn and(self, other: FilterSpec) -> FilterSpec { FilterSpec::And(Box::new(self), Box::new(other)) } @@ -253,7 +294,8 @@ impl KVFilter { let mut evaluating_serializer = EvaluateFilterSerializer { filter: Filter::from_spec(&self.config.filter_spec), message_level: record.level(), - tmp_string: String::new(), + msg: record.msg(), + tmp_value_string: String::new(), }; macro_rules! serialize_and_return_if_decided { @@ -306,21 +348,24 @@ impl KVFilter { AcceptOrReject::Reject } } + Filter::MatchMsgRegex(_) => { + AcceptOrReject::Reject + } Filter::And(a, b) => { if final_evaluate_filter(a, level) == AcceptOrReject::Accept && final_evaluate_filter(b, level) == AcceptOrReject::Accept - { - AcceptOrReject::Accept - } else { + { + AcceptOrReject::Accept + } else { AcceptOrReject::Reject } } Filter::Or(a, b) => { if final_evaluate_filter(a, level) == AcceptOrReject::Accept || final_evaluate_filter(b, level) == AcceptOrReject::Accept - { - AcceptOrReject::Accept - } else { + { + AcceptOrReject::Accept + } else { AcceptOrReject::Reject } } @@ -344,8 +389,8 @@ impl KVFilter { } impl Drain for KVFilter -where - D: Drain, + where + D: Drain, { type Ok = Option; type Err = Option; @@ -381,6 +426,7 @@ enum AcceptOrReject { enum Filter<'a> { Accept, Reject, + LevelAtLeast(Level), MatchKV { key: &'a str, value: &'a str, @@ -389,7 +435,7 @@ enum Filter<'a> { key: &'a str, values: HashSet<&'a str>, }, - LevelAtLeast(Level), + MatchMsgRegex(&'a RegexWrapper), And(Box>, Box>), Or(Box>, Box>), Not(Box>), @@ -400,6 +446,7 @@ impl<'a> Filter<'a> { match spec { FilterSpec::Accept => Filter::Accept, FilterSpec::Reject => Filter::Reject, + FilterSpec::LevelAtLeast(level) => Filter::LevelAtLeast(*level), FilterSpec::MatchKV { key, value } => Filter::MatchKV { key: &key, value: &value, @@ -408,7 +455,7 @@ impl<'a> Filter<'a> { key: &key, values: values.iter().map(|v| v.as_str()).collect(), }, - FilterSpec::LevelAtLeast(level) => Filter::LevelAtLeast(*level), + FilterSpec::MatchMsgRegex(regex_wrapper) => Filter::MatchMsgRegex(®ex_wrapper), FilterSpec::And(a, b) => Filter::And( Box::new(Filter::from_spec(&a)), Box::new(Filter::from_spec(&b)), @@ -433,6 +480,13 @@ struct ArgumentsValueMemo<'a> { } impl<'a> ArgumentsValueMemo<'a> { + fn new(arguments: &'a fmt::Arguments) -> ArgumentsValueMemo<'a> { + ArgumentsValueMemo { + arguments, + is_serialized: Cell::new(false), + } + } + fn is_equal(&self, value: &str, tmp_string: &mut String) -> Result { if !self.is_serialized.get() { tmp_string.clear(); @@ -459,34 +513,45 @@ impl<'a> ArgumentsValueMemo<'a> { /// This is the filtering workhorse. It used to process a single log message. /// It is set up with the logging level of the log message and a filter. -/// `tmp_str` is there just to avoid repeated string allocation and serves as +/// `tmp_value_string` is there just to avoid repeated string allocation and serves as /// a temporary serialized string for `ArgumentsValueMemo` struct EvaluateFilterSerializer<'a> { message_level: Level, + msg: &'a fmt::Arguments<'a>, filter: Filter<'a>, - tmp_string: String, + tmp_value_string: String, } impl<'a> Serializer for EvaluateFilterSerializer<'a> { fn emit_arguments(&mut self, key: Key, value: &fmt::Arguments) -> slog::Result { - let mut value = ArgumentsValueMemo { - arguments: value, - is_serialized: Cell::new(false), - }; + let mut value = ArgumentsValueMemo::new(value); + + struct Context<'a> { + level: Level, + msg: &'a fmt::Arguments<'a>, + key: Key, + value: &'a mut ArgumentsValueMemo<'a>, + tmp_value_string: &'a mut String, + } /// (Partially) in-place evaluate the filter for a particular key and value fn evaluate_filter_with_kv( filter: &mut Filter, - level: Level, - key: Key, - value: &mut ArgumentsValueMemo, - tmp_string: &mut String, + context: &mut Context, ) -> slog::Result { let maybe_simplified_filter = match filter { Filter::Accept => None, Filter::Reject => None, + Filter::MatchMsgRegex(RegexWrapper(regex)) => { + let message = fmt::format(*context.msg); + if regex.is_match(&message) { + Some(Filter::Accept) + } else { + Some(Filter::Reject) + } + } Filter::LevelAtLeast(treshold) => { - if level.is_at_least(*treshold) { + if context.level.is_at_least(*treshold) { Some(Filter::Accept) } else { Some(Filter::Reject) @@ -496,8 +561,8 @@ impl<'a> Serializer for EvaluateFilterSerializer<'a> { key: this_key, value: this_value, } => { - if &key == this_key { - if value.is_equal(this_value, tmp_string)? { + if &context.key == this_key { + if context.value.is_equal(this_value, context.tmp_value_string)? { Some(Filter::Accept) } else { None @@ -510,8 +575,8 @@ impl<'a> Serializer for EvaluateFilterSerializer<'a> { key: this_key, values, } => { - if &key == this_key { - value.remove_from_hash_set(values, tmp_string)?; + if &context.key == this_key { + context.value.remove_from_hash_set(values, context.tmp_value_string)?; if values.is_empty() { Some(Filter::Accept) } else { @@ -522,11 +587,11 @@ impl<'a> Serializer for EvaluateFilterSerializer<'a> { } } Filter::And(a, b) => { - evaluate_filter_with_kv(a, level, key, value, tmp_string)?; + evaluate_filter_with_kv(a, context)?; if **a == Filter::Reject { Some(Filter::Reject) } else { - evaluate_filter_with_kv(b, level, key, value, tmp_string)?; + evaluate_filter_with_kv(b, context)?; if **a == Filter::Accept { if **b == Filter::Accept { Some(Filter::Accept) @@ -541,11 +606,11 @@ impl<'a> Serializer for EvaluateFilterSerializer<'a> { } } Filter::Or(a, b) => { - evaluate_filter_with_kv(a, level, key, value, tmp_string)?; + evaluate_filter_with_kv(a, context)?; if **a == Filter::Accept { Some(Filter::Accept) } else { - evaluate_filter_with_kv(b, level, key, value, tmp_string)?; + evaluate_filter_with_kv(b, context)?; if **b == Filter::Accept { Some(Filter::Accept) } else if **a == Filter::Reject && **b == Filter::Reject { @@ -556,7 +621,7 @@ impl<'a> Serializer for EvaluateFilterSerializer<'a> { } } Filter::Not(f) => { - evaluate_filter_with_kv(f, level, key, value, tmp_string)?; + evaluate_filter_with_kv(f, context)?; if **f == Filter::Accept { Some(Filter::Reject) } else if **f == Filter::Reject { @@ -574,12 +639,17 @@ impl<'a> Serializer for EvaluateFilterSerializer<'a> { Ok(()) } + let mut context = Context { + level: self.message_level, + msg: self.msg, + key, + value: &mut value, + tmp_value_string: &mut self.tmp_value_string, + }; + evaluate_filter_with_kv( &mut self.filter, - self.message_level, - key, - &mut value, - &mut self.tmp_string, + &mut context, )?; Ok(()) @@ -915,6 +985,20 @@ mod tests { tester.assert_accepted(4); } + #[test] + fn test_match_msg_regex() { + let tester = Tester::new( + FilterSpec::try_match_msg_regex(r"Foo.*Bar").unwrap(), + EvaluationOrder::LoggerAndMessage, + ); + info!(tester.log, "ACCEPT FooBar"); + info!(tester.log, "ACCEPT FooBarFooBar"); + info!(tester.log, "ACCEPT FooQuxBar"); + info!(tester.log, "REJECT Foo"); + info!(tester.log, "REJECT"); + tester.assert_accepted(3); + } + #[test] fn test_and() { { From e5cb44ffe78e974457b08323f7e6df608e5a3a25 Mon Sep 17 00:00:00 2001 From: Tomas Dvorak Date: Fri, 5 Oct 2018 20:56:29 +0200 Subject: [PATCH 15/23] Better module comment --- src/lib.rs | 91 ++++++++++++++++++++++++++++++++++++------------------ 1 file changed, 61 insertions(+), 30 deletions(-) diff --git a/src/lib.rs b/src/lib.rs index 455613d..a6ad874 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -1,7 +1,45 @@ -//! Filter records by matching their keys and values, and allows arbitrary -//! Bool logic expressions to be used. +//! Filter records by matching their messages, keys and values. Records can be matched //! -//! See the unit tests (especially `test_complex_example` and `test_complex_example_2`) to see how to use it. +//! - based on logging level (debug, info, warn, ...) +//! - regular expression on record message +//! - keys and values +//! - simple records can be arbitrarily composed using `And`, `Or` and `Not` expressions +//! +//! # Examples +//! +//! This is an example that implements the behavior requested at this [issue](https://github.com/sile/sloggers/issues/9#issuecomment-422685244) +//! +//! The requested behavior: +//! +//! 1. pass all records with ("subsystem": "A1" || "subsystem": "A2") && level at least debug +//! 2. pass all records with (subsystem": "B1" || "subsystem": "B2") && level at least info +//! 3. pass all records with level at least warn +//! 4. reject all other records +//! +//! In all cases, make decisions based only on the LOGGER keys and values, don't take the message KVs into account +//! ``` +//! extern crate slog; +//! extern crate slog_kvfilter; +//! +//! use slog_kvfilter::FilterSpec; +//! use slog::Level; +//! +//! let match_kv = FilterSpec::match_kv; +//! +//! let subsystem_a = (match_kv("subsystem", "A1").or(match_kv("subsystem", "A2"))) +//! .and(FilterSpec::LevelAtLeast(Level::Debug)); +//! +//! let subsystem_b = (match_kv("subsystem", "B1").or(match_kv("subsystem", "B2"))) +//! .and(FilterSpec::LevelAtLeast(Level::Info)); +//! +//! // `And` and `Or` rules are evaluated first-to-last, so put the simplest rules (`LevelAtLeast`) first so the filter +//! // doesn't have to evaluate the more complicated rules if the simpler one already decides a message's fate +//! let filter = FilterSpec::LevelAtLeast(Level::Warning) +//! .or(subsystem_a) +//! .or(subsystem_b); +//!``` +//! +//! See the unit tests for more example usage. //! #[cfg(feature = "serde")] @@ -14,9 +52,9 @@ extern crate serde_regex; #[macro_use] extern crate slog; +extern crate regex; #[cfg(not(test))] extern crate slog; -extern crate regex; use std::cell::Cell; use std::collections::HashSet; @@ -53,7 +91,6 @@ enum LevelSerdeDef { Trace, } - /// Just a wrapper around Regex to provide /// /// - Serde support @@ -61,10 +98,7 @@ enum LevelSerdeDef { /// - `impl UnwindSafe` - the wrapped Regex is not UnwindSafe, we mark RegexWrapper as being so. #[cfg_attr(feature = "serde", derive(Serialize, Deserialize))] #[derive(Clone, Debug)] -pub struct RegexWrapper( - #[cfg_attr(feature = "serde", serde(with = "serde_regex"))] - Regex -); +pub struct RegexWrapper(#[cfg_attr(feature = "serde", serde(with = "serde_regex"))] Regex); // Just cargo-culting here. I'm not sure what are the actual implications of Regex // not being Unwind-safe :-( @@ -348,24 +382,22 @@ impl KVFilter { AcceptOrReject::Reject } } - Filter::MatchMsgRegex(_) => { - AcceptOrReject::Reject - } + Filter::MatchMsgRegex(_) => AcceptOrReject::Reject, Filter::And(a, b) => { if final_evaluate_filter(a, level) == AcceptOrReject::Accept && final_evaluate_filter(b, level) == AcceptOrReject::Accept - { - AcceptOrReject::Accept - } else { + { + AcceptOrReject::Accept + } else { AcceptOrReject::Reject } } Filter::Or(a, b) => { if final_evaluate_filter(a, level) == AcceptOrReject::Accept || final_evaluate_filter(b, level) == AcceptOrReject::Accept - { - AcceptOrReject::Accept - } else { + { + AcceptOrReject::Accept + } else { AcceptOrReject::Reject } } @@ -389,8 +421,8 @@ impl KVFilter { } impl Drain for KVFilter - where - D: Drain, +where + D: Drain, { type Ok = Option; type Err = Option; @@ -535,10 +567,7 @@ impl<'a> Serializer for EvaluateFilterSerializer<'a> { } /// (Partially) in-place evaluate the filter for a particular key and value - fn evaluate_filter_with_kv( - filter: &mut Filter, - context: &mut Context, - ) -> slog::Result { + fn evaluate_filter_with_kv(filter: &mut Filter, context: &mut Context) -> slog::Result { let maybe_simplified_filter = match filter { Filter::Accept => None, Filter::Reject => None, @@ -562,7 +591,10 @@ impl<'a> Serializer for EvaluateFilterSerializer<'a> { value: this_value, } => { if &context.key == this_key { - if context.value.is_equal(this_value, context.tmp_value_string)? { + if context + .value + .is_equal(this_value, context.tmp_value_string)? + { Some(Filter::Accept) } else { None @@ -576,7 +608,9 @@ impl<'a> Serializer for EvaluateFilterSerializer<'a> { values, } => { if &context.key == this_key { - context.value.remove_from_hash_set(values, context.tmp_value_string)?; + context + .value + .remove_from_hash_set(values, context.tmp_value_string)?; if values.is_empty() { Some(Filter::Accept) } else { @@ -647,10 +681,7 @@ impl<'a> Serializer for EvaluateFilterSerializer<'a> { tmp_value_string: &mut self.tmp_value_string, }; - evaluate_filter_with_kv( - &mut self.filter, - &mut context, - )?; + evaluate_filter_with_kv(&mut self.filter, &mut context)?; Ok(()) } From 49ff1f57baa8c5361417c55a5b1f5f7a5ffe5fb2 Mon Sep 17 00:00:00 2001 From: Tomas Dvorak Date: Fri, 5 Oct 2018 21:10:58 +0200 Subject: [PATCH 16/23] Better README, version bumped to 0.7.0 --- Cargo.toml | 2 +- README.md | 21 +++++++++++++++++---- src/lib.rs | 2 +- 3 files changed, 19 insertions(+), 6 deletions(-) diff --git a/Cargo.toml b/Cargo.toml index 23a3692..52c0ea5 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -1,6 +1,6 @@ [package] name = "slog-kvfilter" -version = "0.6.1" +version = "0.7.0" authors = ["Dawid Ciężarkiewicz ", "Tony Przygienda "] description = "Key values and Regex based filter Drain for slog-rs" keywords = ["slog", "logging", "log", "filter"] diff --git a/README.md b/README.md index c73b46f..4d28a27 100644 --- a/README.md +++ b/README.md @@ -20,9 +20,22 @@ # slog-kvfilter - Key values and Regex based filter Drain for [slog-rs] -For more information, help, to report issues etc. see [slog-rs][slog-rs]. +Filter records by matching their messages, keys and values. Records can be matched -[slog-rs]: https://github.com/slog-rs/slog + - based on logging level (debug, info, warn, ...) + - regular expression on record message + - keys and values + - simple filters can be arbitrarily composed using `And`, `Or` and `Not` expressions -Documentation can be found on -[`slog-kvfilter` type](https://docs.rs/slog-kvfilter/*/slog-kvfilter/index.html). \ No newline at end of file + +**slog-kvfilter has undergone a complete rewrite as of version 0.7.0. +The API has changed. See [this issue](https://github.com/slog-rs/kvfilter/issues/15) +for details.** + +slog-kvfilter documentation can be found [here](https://docs.rs/slog-kvfilter/*/slog_kvfilter/). + +For more information, help, to report issues etc. see +[slog-kvfilter][slog-kvfilter] and [slog-rs][slog-rs]. + +[slog-kvfilter]: https://github.com/slog-rs/kvfilter/ +[slog-rs]: https://github.com/slog-rs/slog \ No newline at end of file diff --git a/src/lib.rs b/src/lib.rs index a6ad874..d4fdff3 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -3,7 +3,7 @@ //! - based on logging level (debug, info, warn, ...) //! - regular expression on record message //! - keys and values -//! - simple records can be arbitrarily composed using `And`, `Or` and `Not` expressions +//! - simple filters can be arbitrarily composed using `And`, `Or` and `Not` expressions //! //! # Examples //! From 4ed5652a89ba644bed921d4044550be51b555249 Mon Sep 17 00:00:00 2001 From: Tomas Dvorak Date: Fri, 5 Oct 2018 21:17:32 +0200 Subject: [PATCH 17/23] Alright, added myself as well to Authors in Cargo.toml :-) --- Cargo.toml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/Cargo.toml b/Cargo.toml index 52c0ea5..a99c386 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -1,7 +1,7 @@ [package] name = "slog-kvfilter" version = "0.7.0" -authors = ["Dawid Ciężarkiewicz ", "Tony Przygienda "] +authors = ["Dawid Ciężarkiewicz ", "Tony Przygienda ", "Tomáš Dvořák "] description = "Key values and Regex based filter Drain for slog-rs" keywords = ["slog", "logging", "log", "filter"] license = "MPL-2.0/MIT/Apache-2.0" From 6efb7dd8c362c85edb40f9ddf7347962ba773712 Mon Sep 17 00:00:00 2001 From: Tomas Dvorak Date: Sat, 6 Oct 2018 08:15:01 +0200 Subject: [PATCH 18/23] Make tests pass even in release mode --- Cargo.toml | 8 +++++++- 1 file changed, 7 insertions(+), 1 deletion(-) diff --git a/Cargo.toml b/Cargo.toml index a99c386..03cfa5d 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -18,5 +18,11 @@ default=["serde", "serde_regex"] [dependencies] serde = { version = "1", optional = true, features = ["derive"] } serde_regex = { version = "0", optional = true } -slog = "2" regex = "1" + + +[dependencies.slog] +version = "2" +default-features = false +# So that the tests can reliably use debug and trace macros +features = ["max_level_trace", "release_max_level_trace", "std"] From d19f5cd961e1d871fba2309695a3c89b5e42a56b Mon Sep 17 00:00:00 2001 From: Tomas Dvorak Date: Sat, 6 Oct 2018 22:33:27 +0200 Subject: [PATCH 19/23] Actually construct KVFilter in the module-level example --- src/lib.rs | 12 ++++++++---- 1 file changed, 8 insertions(+), 4 deletions(-) diff --git a/src/lib.rs b/src/lib.rs index d4fdff3..a18441b 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -16,13 +16,14 @@ //! 3. pass all records with level at least warn //! 4. reject all other records //! -//! In all cases, make decisions based only on the LOGGER keys and values, don't take the message KVs into account +//! In all cases, make decisions based only on the LOGGER keys and values, +//! don't take the message KVs into account (`EvaluationOrder::LoggerOnly`) //! ``` //! extern crate slog; //! extern crate slog_kvfilter; //! -//! use slog_kvfilter::FilterSpec; -//! use slog::Level; +//! use slog_kvfilter::{EvaluationOrder, FilterSpec, KVFilter}; +//! use slog::{Discard, Level}; //! //! let match_kv = FilterSpec::match_kv; //! @@ -34,9 +35,12 @@ //! //! // `And` and `Or` rules are evaluated first-to-last, so put the simplest rules (`LevelAtLeast`) first so the filter //! // doesn't have to evaluate the more complicated rules if the simpler one already decides a message's fate -//! let filter = FilterSpec::LevelAtLeast(Level::Warning) +//! let filter_spec = FilterSpec::LevelAtLeast(Level::Warning) //! .or(subsystem_a) //! .or(subsystem_b); +//! let root_drain = Discard; +//! let kv_filter = KVFilter::new(root_drain, filter_spec, EvaluationOrder::LoggerOnly); +//! // Use the kv_filter as your `Drain` //!``` //! //! See the unit tests for more example usage. From ff10e5c40b7c9fbbb7e92de4d48bea5dd5c23756 Mon Sep 17 00:00:00 2001 From: Tomas Dvorak Date: Sun, 14 Oct 2018 11:20:00 +0200 Subject: [PATCH 20/23] MatchAllValues => MatchAnyValue --- src/lib.rs | 92 ++++++++++++++++++++++++------------------------------ 1 file changed, 41 insertions(+), 51 deletions(-) diff --git a/src/lib.rs b/src/lib.rs index a18441b..ccf902e 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -138,13 +138,13 @@ pub enum FilterSpec { MatchKV { key: String, value: String }, /// Accept when all `values` for a given `key` are present. /// - /// Equivalent to `MatchKV {key, value1}.and(MatchKV {key, value2}).and(...)`, - /// but is implemented using a `HashSet` instead of a linked `And` structure, so + /// Equivalent to `MatchKV {key, value1}.or(MatchKV {key, value2}).or(...)`, + /// but is implemented using a `HashSet` instead of a linked `Or` structure, so /// it will be more performant for a larger number of values /// (no benchmarks done, but my guess is > 3 values). /// /// Always accepts on empty `values` - MatchAllValues { key: String, values: Vec }, + MatchAnyValue { key: String, values: Vec }, /// Accept when the log message matches the given regular expression. MatchMsgRegex(RegexWrapper), /// Accept when all the sub-filters accept. Sub-filter are evaluated left-to-right. @@ -169,8 +169,8 @@ impl FilterSpec { } } - pub fn match_all_values(key: impl ToString, values: &[impl ToString]) -> FilterSpec { - FilterSpec::MatchAllValues { + pub fn match_any_value(key: impl ToString, values: &[impl ToString]) -> FilterSpec { + FilterSpec::MatchAnyValue { key: key.to_string(), values: values.iter().map(|v| v.to_string()).collect(), } @@ -379,7 +379,7 @@ impl KVFilter { } } Filter::MatchKV { .. } => AcceptOrReject::Reject, - Filter::MatchAllValues { values, .. } => { + Filter::MatchAnyValue { values, .. } => { if values.is_empty() { AcceptOrReject::Accept } else { @@ -390,18 +390,18 @@ impl KVFilter { Filter::And(a, b) => { if final_evaluate_filter(a, level) == AcceptOrReject::Accept && final_evaluate_filter(b, level) == AcceptOrReject::Accept - { - AcceptOrReject::Accept - } else { + { + AcceptOrReject::Accept + } else { AcceptOrReject::Reject } } Filter::Or(a, b) => { if final_evaluate_filter(a, level) == AcceptOrReject::Accept || final_evaluate_filter(b, level) == AcceptOrReject::Accept - { - AcceptOrReject::Accept - } else { + { + AcceptOrReject::Accept + } else { AcceptOrReject::Reject } } @@ -425,8 +425,8 @@ impl KVFilter { } impl Drain for KVFilter -where - D: Drain, + where + D: Drain, { type Ok = Option; type Err = Option; @@ -467,7 +467,7 @@ enum Filter<'a> { key: &'a str, value: &'a str, }, - MatchAllValues { + MatchAnyValue { key: &'a str, values: HashSet<&'a str>, }, @@ -487,7 +487,7 @@ impl<'a> Filter<'a> { key: &key, value: &value, }, - FilterSpec::MatchAllValues { key, values } => Filter::MatchAllValues { + FilterSpec::MatchAnyValue { key, values } => Filter::MatchAnyValue { key: &key, values: values.iter().map(|v| v.as_str()).collect(), }, @@ -532,18 +532,13 @@ impl<'a> ArgumentsValueMemo<'a> { Ok(tmp_string == value) } - fn remove_from_hash_set( - &self, - set: &mut HashSet<&str>, - tmp_string: &mut String, - ) -> Result<(), fmt::Error> { + fn is_contained_in_hash_set(&self, set: &HashSet<&str>, tmp_string: &mut String) -> Result { if !self.is_serialized.get() { tmp_string.clear(); fmt::write(tmp_string, *self.arguments)?; self.is_serialized.set(true); } - set.remove(tmp_string.as_str()); - Ok(()) + Ok(set.contains(tmp_string.as_str())) } } @@ -598,28 +593,23 @@ impl<'a> Serializer for EvaluateFilterSerializer<'a> { if context .value .is_equal(this_value, context.tmp_value_string)? - { - Some(Filter::Accept) - } else { + { + Some(Filter::Accept) + } else { None } } else { None } } - Filter::MatchAllValues { + Filter::MatchAnyValue { key: this_key, values, } => { - if &context.key == this_key { - context - .value - .remove_from_hash_set(values, context.tmp_value_string)?; - if values.is_empty() { - Some(Filter::Accept) - } else { - None - } + if &context.key == this_key && + context.value + .is_contained_in_hash_set(values, context.tmp_value_string)? { + Some(Filter::Accept) } else { None } @@ -1004,19 +994,18 @@ mod tests { } #[test] - fn test_match_all_values() { + fn test_match_any_value() { let tester = Tester::new( - FilterSpec::match_all_values("key", &["v1", "v2", "v3"]), + FilterSpec::match_any_value("key", &["v1", "v2", "v3"]), EvaluationOrder::LoggerAndMessage, ); - info!(tester.log, "ACCEPT"; "key" => "v1", "key" => "v2", "key" => "v3"); - info!(tester.log, "ACCEPT"; "key" => "v3", "key" => "v3", "key" => "v1", "key" => "v2"); - info!(tester.log, "ACCEPT"; "key" => "v3", "key" => "v5", "key" => "v1", "key" => "v2"); + info!(tester.log, "ACCEPT"; "key" => "v1"); + info!(tester.log, "ACCEPT"; "key" => "v3"); + info!(tester.log, "ACCEPT"; "key" => "foo", "key" => "v2", "key" => "bar"); info!(tester.log, "ACCEPT"; "key" => "v3", "key" => "v1", "key" => "v2", "key" => "v5",); info!(tester.log, "REJECT"); - info!(tester.log, "REJECT"; "key" => "v2", "key" => "v3"); - info!(tester.log, "REJECT"; "key" => "v1", "key" => "v3"); - info!(tester.log, "REJECT"; "key" => "v1", "key" => "v5", "key" => "v3"); + info!(tester.log, "REJECT"; "key" => "foo", "key" => "bar"); + info!(tester.log, "REJECT"; "bad_key" => "v1"); tester.assert_accepted(4); } @@ -1090,16 +1079,17 @@ mod tests { // level: Debug (that actually means level at least Info) // } - let match_kv = FilterSpec::match_kv; - // (key1 must be either value1a or value1b) AND key2 must be value2 - let positive_filter = (match_kv("key1", "value1a").or(match_kv("key1", "value1b"))) - .and(match_kv("key2", "value2")); + let positive_filter = FilterSpec::all_of(&[ + FilterSpec::match_any_value("key1", &["value1a", "value1b"]), + FilterSpec::match_kv("key2", "value2") + ]); // neg_key1 must be neg_value1 OR neg_key2 must be neg_value2a OR neg_key2 must be neg_value2b - let negative_filter = match_kv("neg_key1", "neg_value1") - .or(match_kv("neg_key2", "neg_value2a")) - .or(match_kv("neg_key2", "neg_value2b")); + let negative_filter = FilterSpec::any_of(&[ + FilterSpec::match_kv("neg_key1", "neg_value1"), + FilterSpec::match_any_value("neg_key2", &["neg_value2a", "neg_value2b"]), + ]); // We pass everything with level at least info, OR anything that matches the positive filter but not the negative one. // `And` and `Or` rules are evaluated first-to-last, so put the simplest rules (`LevelAtLeast`) first so the filter From d0be0a3b02845ecbc12392a5ad8f5235ba72b8bb Mon Sep 17 00:00:00 2001 From: Tomas Dvorak Date: Sun, 14 Oct 2018 13:28:08 +0200 Subject: [PATCH 21/23] Criterion benchmark --- Cargo.toml | 7 + benches/kvfilter_benchmark.rs | 264 ++++++++++++++++++++++++++++++++++ 2 files changed, 271 insertions(+) create mode 100644 benches/kvfilter_benchmark.rs diff --git a/Cargo.toml b/Cargo.toml index 03cfa5d..6579954 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -26,3 +26,10 @@ version = "2" default-features = false # So that the tests can reliably use debug and trace macros features = ["max_level_trace", "release_max_level_trace", "std"] + +[dev-dependencies] +criterion = "0.2" + +[[bench]] +name = "kvfilter_benchmark" +harness = false diff --git a/benches/kvfilter_benchmark.rs b/benches/kvfilter_benchmark.rs new file mode 100644 index 0000000..935130c --- /dev/null +++ b/benches/kvfilter_benchmark.rs @@ -0,0 +1,264 @@ +#[macro_use] +extern crate criterion; +#[macro_use] +extern crate slog; +extern crate slog_kvfilter; + +use std::sync::Arc; +use std::sync::atomic::{AtomicUsize, Ordering}; + +use criterion::Criterion; +use slog::{Drain, Logger, Never, Record, OwnedKVList, Level}; +use slog_kvfilter::{EvaluationOrder, FilterSpec, KVFilter}; + +#[derive(Debug, Clone)] +pub struct CountingDrain { + count: Arc +} + +impl Drain for CountingDrain { + type Ok = (); + type Err = Never; + + fn log(&self, _: &Record, _: &OwnedKVList) -> Result<(), Never> { + self.count.fetch_add(1, Ordering::Relaxed); + Ok(()) + } + + #[inline] + fn is_enabled(&self, _: Level) -> bool { + true + } +} + +struct Tester { + log: Logger, + count: Arc, +} + +impl Tester { + fn assert_count(&self, expected_count: usize) { + let actual_count = self.count.load(Ordering::Relaxed); + assert_eq!(expected_count, actual_count) + } +} + +fn new_tester(spec: FilterSpec, evaluation_order: EvaluationOrder) -> Tester { + let count = Arc::new(AtomicUsize::new(0)); + let drain = KVFilter::new( + CountingDrain { count: Arc::clone(&count) }, + spec, + evaluation_order, + ); + Tester { + log: Logger::root(drain.fuse(), o!("key_foo" => "value_foo")), + count, + } +} + + +// simple AND use_case - useful for comparison with original KVFilter in simple cases +fn simple_and_benchmark(c: &mut Criterion) { + let tester = { + let match_kv = FilterSpec::match_kv; + + let filter_spec = FilterSpec::all_of(&[ + match_kv("some_key", "some_value"), + match_kv("another_key", "another_value"), + ]); + + new_tester(filter_spec, EvaluationOrder::LoggerAndMessage) + }; + + let mut first_iteration = true; + c.bench_function("simple AND", move |b| { + b.iter(|| { + info!(tester.log, "ACCEPT"; + "some_key" => "some_value", + "another_key" => "another_value", + ); + + debug!(tester.log, "REJECT"; + "some_key" => "some_value", + ); + + trace!(tester.log, "REJECT"; + "another_key" => "another_value", + "bad_key" => "bad_key", + ); + + if first_iteration { + tester.assert_count(1); + first_iteration = false; + } + }) + }); +} + +// simple OR use_case - not expressible in original KVFilter +fn simple_or_benchmark(c: &mut Criterion) { + let tester = { + let match_kv = FilterSpec::match_kv; + let level_at_least = FilterSpec::LevelAtLeast; + + let filter_spec = FilterSpec::any_of(&[ + match_kv("debug_key", "debug_value").and(level_at_least(Level::Debug)), + match_kv("trace_key", "trace_value").and(level_at_least(Level::Trace)), + ]); + + new_tester(filter_spec, EvaluationOrder::LoggerAndMessage) + }; + + let mut first_iteration = true; + c.bench_function("simple OR", move |b| { + b.iter(|| { + info!(tester.log, "REJECT"; + "some_key" => "some_value", + "another_key" => "another_value", + ); + + debug!(tester.log, "ACCEPT"; + "another_key" => "another_value", + "debug_key" => "debug_value", + ); + + trace!(tester.log, "REJECT"; + "debug_key" => "debug_value", + "another_key" => "another_value", + ); + + trace!(tester.log, "ACCEPT"; + "trace_key" => "trace_value", + "another_key" => "another_value", + ); + + if first_iteration { + tester.assert_count(2); + first_iteration = false; + } + }) + }); +} + +// @przygienda use-case +fn przygienda_tester() -> Tester { + let match_any = FilterSpec::match_any_value; + + // (key1 must be either value1a or value1b) AND key2 must be value2 + let positive_filter = FilterSpec::all_of(&[ + match_any( + "some_key", + &[ + "some_value_1", + "some_value_2", + "some_value_3", + "some_value_4", + "foo", + ], + ), + match_any( + "another_key", + &[ + "another_value_1", + "another_value_2", + "another_value_3", + "another_value_4", + "bar", + ], + ), + match_any( + "key_foo", + &[ + "foo_value_1", + "foo_value_2", + "foo_value_3", + "foo_value_4", + "value_foo", + ], + ), + match_any( + "bar_key", + &[ + "bar_value_1", + "bar_value_2", + "bar_value_3", + "bar_value_4", + "xyz", + ], + ), + match_any( + "ultimate_key", + &[ + "ultimate_value_1", + "ultimate_value_2", + "ultimate_value_3", + "ultimate_value_4", + "xyz", + ], + ), + ]); + + // neg_key1 must be neg_value1 OR neg_key2 must be neg_value2a OR neg_key2 must be neg_value2b + let negative_filter = FilterSpec::any_of(&[ + match_any( + "some_negative_key", + &[ + "some_value_1", + "some_value_2", + "some_value_3", + "some_value_4", + "foo", + ], + ), + match_any( + "another_negative_key", + &[ + "some_value_1", + "some_value_2", + "some_value_3", + "some_value_4", + "foo", + ], + ), + ]); + + let filter_spec = positive_filter.and(negative_filter.not()); + new_tester(filter_spec, EvaluationOrder::LoggerAndMessage) +} + + +fn przygienda_benchmark(c: &mut Criterion) { + let tester = przygienda_tester(); + let mut first_iteration = true; + c.bench_function("przygienda", move |b| { + b.iter(|| { + info!(tester.log, "ACCEPT"; + "some_key" => "some_value_4", + "another_key" => "another_value_1", + "bar_key" => "bar_value_3", + "ultimate_key" => "ultimate_value_3", + ); + + info!(tester.log, "REJECT - negative filter"; + "some_key" => "some_value_4", + "another_key" => "another_value_1", + "bar_key" => "bar_value_3", + "ultimate_key" => "ultimate_value_3", + "some_negative_key" => "foo" + ); + + info!(tester.log, "REJECT - not all keys present"; + "some_key" => "some_value_4", + "another_key" => "another_value_1", + ); + + if first_iteration { + tester.assert_count(1); + first_iteration = false; + } + }) + }); +} + +criterion_group!(benches, simple_and_benchmark, przygienda_benchmark, simple_or_benchmark); +criterion_main!(benches); From f856384d9b6bbfbeb531152d439aabc4f3a4afe9 Mon Sep 17 00:00:00 2001 From: Tomas Dvorak Date: Thu, 11 Mar 2021 04:49:49 +0100 Subject: [PATCH 22/23] feat: FilterSpec::KeyExists --- Cargo.toml | 4 +- src/lib.rs | 126 ++++++++++++++++++++++++++++++++++++++++------------- 2 files changed, 98 insertions(+), 32 deletions(-) diff --git a/Cargo.toml b/Cargo.toml index 6579954..f97c5c3 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -22,10 +22,10 @@ regex = "1" [dependencies.slog] -version = "2" +version = "2.7" default-features = false # So that the tests can reliably use debug and trace macros -features = ["max_level_trace", "release_max_level_trace", "std"] +features = ["max_level_trace", "release_max_level_trace", "std", "dynamic-keys"] [dev-dependencies] criterion = "0.2" diff --git a/src/lib.rs b/src/lib.rs index ccf902e..5405316 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -46,30 +46,30 @@ //! See the unit tests for more example usage. //! +extern crate regex; #[cfg(feature = "serde")] #[macro_use] extern crate serde; #[cfg(feature = "serde")] extern crate serde_regex; - #[cfg(test)] #[macro_use] extern crate slog; - -extern crate regex; #[cfg(not(test))] extern crate slog; -use std::cell::Cell; -use std::collections::HashSet; -use std::fmt; -use std::panic::{RefUnwindSafe, UnwindSafe}; +use std::{ + cell::Cell, + collections::HashSet, + fmt, + panic::{RefUnwindSafe, UnwindSafe}, +}; use regex::Regex; -use slog::{Drain, Key, Level, OwnedKVList, Record, Serializer, KV}; -// ========== public KVFilter configuration +use slog::{Drain, Key, KV, Level, OwnedKVList, Record, Serializer}; +//region KVFilterConfig /// All the configuration for a KVFilter /// /// If compiled with the "serde" feature, the config can be serialized and deserialized using Serde. @@ -147,6 +147,8 @@ pub enum FilterSpec { MatchAnyValue { key: String, values: Vec }, /// Accept when the log message matches the given regular expression. MatchMsgRegex(RegexWrapper), + /// Accepts when the key is present + KeyExists(String), /// Accept when all the sub-filters accept. Sub-filter are evaluated left-to-right. /// /// Please note that slog processes KV arguments to `log!` right to left, that is e. g. @@ -184,6 +186,10 @@ impl FilterSpec { Ok(Self::match_msg_regex(Regex::new(regex)?)) } + pub fn key_exists(key: impl ToString) -> FilterSpec { + FilterSpec::KeyExists(key.to_string()) + } + pub fn and(self, other: FilterSpec) -> FilterSpec { FilterSpec::And(Box::new(self), Box::new(other)) } @@ -261,7 +267,9 @@ impl Default for EvaluationOrder { EvaluationOrder::LoggerAndMessage } } +//endregion +//region KVFilter /// The KVFilter itself. It implements `Drain`. /// /// It passes messages matching the criteria specified by a given `config` into an underlying `drain` @@ -387,21 +395,22 @@ impl KVFilter { } } Filter::MatchMsgRegex(_) => AcceptOrReject::Reject, + Filter::KeyExists(_) => AcceptOrReject::Reject, Filter::And(a, b) => { if final_evaluate_filter(a, level) == AcceptOrReject::Accept && final_evaluate_filter(b, level) == AcceptOrReject::Accept - { - AcceptOrReject::Accept - } else { + { + AcceptOrReject::Accept + } else { AcceptOrReject::Reject } } Filter::Or(a, b) => { if final_evaluate_filter(a, level) == AcceptOrReject::Accept || final_evaluate_filter(b, level) == AcceptOrReject::Accept - { - AcceptOrReject::Accept - } else { + { + AcceptOrReject::Accept + } else { AcceptOrReject::Reject } } @@ -446,9 +455,9 @@ impl Drain for KVFilter } } } +//endregion -// ========== Implementation - +//region Filtering implementation /// Simple enum to express a message is to be either Accepted or Rejected #[derive(Clone, Copy, Debug, PartialEq)] enum AcceptOrReject { @@ -467,6 +476,7 @@ enum Filter<'a> { key: &'a str, value: &'a str, }, + KeyExists(&'a str), MatchAnyValue { key: &'a str, values: HashSet<&'a str>, @@ -492,6 +502,7 @@ impl<'a> Filter<'a> { values: values.iter().map(|v| v.as_str()).collect(), }, FilterSpec::MatchMsgRegex(regex_wrapper) => Filter::MatchMsgRegex(®ex_wrapper), + FilterSpec::KeyExists(key) => Filter::KeyExists(&key), FilterSpec::And(a, b) => Filter::And( Box::new(Filter::from_spec(&a)), Box::new(Filter::from_spec(&b)), @@ -590,12 +601,9 @@ impl<'a> Serializer for EvaluateFilterSerializer<'a> { value: this_value, } => { if &context.key == this_key { - if context - .value - .is_equal(this_value, context.tmp_value_string)? - { - Some(Filter::Accept) - } else { + if context.value.is_equal(this_value, context.tmp_value_string)? { + Some(Filter::Accept) + } else { None } } else { @@ -614,6 +622,13 @@ impl<'a> Serializer for EvaluateFilterSerializer<'a> { None } } + Filter::KeyExists(this_key) => { + if &context.key == this_key { + Some(Filter::Accept) + } else { + None + } + } Filter::And(a, b) => { evaluate_filter_with_kv(a, context)?; if **a == Filter::Reject { @@ -680,19 +695,26 @@ impl<'a> Serializer for EvaluateFilterSerializer<'a> { Ok(()) } } +//endregion +//region tests #[cfg(test)] mod tests { - use super::FilterSpec::*; - use super::*; - - use std::fmt; - use std::io; - use std::sync::atomic::{AtomicUsize, Ordering}; - use std::sync::{Arc, Mutex}; + use std::{ + fmt, + io, + sync::{ + Arc, + atomic::{AtomicUsize, Ordering}, + Mutex, + }, + }; use slog::{Drain, FnValue, Level, Logger, OwnedKVList, Record}; + use super::*; + use super::FilterSpec::*; + #[derive(Debug)] struct StringDrain { output: Arc>>, @@ -1023,6 +1045,21 @@ mod tests { tester.assert_accepted(3); } + #[test] + fn test_key_exists() { + let tester = Tester::new( + FilterSpec::key_exists("key"), + EvaluationOrder::LoggerAndMessage, + ); + info!(tester.log, "ACCEPT: Good key"; "key" => "value"); + info!(tester.log, "ACCEPT: Good key"; "foo" => "bar", "key" => "value", "bar" => "baz"); + info!(tester.log, "REJECT"; "main_log" => "m"); + info!(tester.log, "REJECT"; "bad_key" => "value"); + info!(tester.log, "REJECT"); + tester.assert_accepted(2); + } + + #[test] fn test_and() { { @@ -1170,4 +1207,33 @@ mod tests { tester.assert_accepted(5); } + + + #[test] + fn test_complex_example_3() { + // Implements https://github.com/slog-rs/kvfilter/pull/16#issuecomment-795856834 + + let tester = Tester::new( + LevelAtLeast(Level::Warning).or( + LevelAtLeast(Level::Info).and( + FilterSpec::key_exists("err") + .and(FilterSpec::match_kv("err", "None").not()) + .and(FilterSpec::match_kv("err", "").not()) + )), + EvaluationOrder::LoggerAndMessage, + ); + + // should discard + info!(tester.log, "REJECT: test info"); + info!(tester.log, "REJECT: test info"; "count" => 10); + info!(tester.log, "REJECT: test error"; "err" => "None"); + info!(tester.log, "REJECT: test error"; "err" => ""); + debug!(tester.log, "REJECT: test debug"); + + // should log to drain + info!(tester.log, "ACCEPT: test error"; "err" => "Panic!"); + error!(tester.log, "ACCEPT: test error"); + tester.assert_accepted(2); + } } +//endregion From a1bad7d18d2157f37fa8d0c842ef089bd0693c2a Mon Sep 17 00:00:00 2001 From: Tomas Dvorak Date: Thu, 11 Mar 2021 22:06:55 +0100 Subject: [PATCH 23/23] feat: Minor test addition --- src/lib.rs | 1 + 1 file changed, 1 insertion(+) diff --git a/src/lib.rs b/src/lib.rs index 5405316..129a30e 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -1228,6 +1228,7 @@ mod tests { info!(tester.log, "REJECT: test info"; "count" => 10); info!(tester.log, "REJECT: test error"; "err" => "None"); info!(tester.log, "REJECT: test error"; "err" => ""); + debug!(tester.log, "REJECT: test debug"; "err" => "Panic!"); debug!(tester.log, "REJECT: test debug"); // should log to drain