Add support for slog_kvfilter

dvtomas commented 6 years ago

Add support to have different logging levels based on slog_kvfilter for both terminal_logger and file_logger.

The configuration could look e.g. something like


type = "terminal" # terminal or file
format = "full" # full or compact
source_location = "module_and_line" # none or module_and_line
timezone = "utc" # utc or local
level = "info" # one of trace, debug, info, warning, error, critical
destination = "stderr" # stderr or stdout

[[kv_filter]]
key="http_server"
values = ["get", "post"]
level="debug"

[[kv_filter]]
key="hw-subsystem"
values = ["camera"]
level="debug"

This would mean dragging in slog_kvfilter as a crate dependency. If not desired, perhaps it could be done as an optional feature.

sile commented 6 years ago

Since kv_filter is a lightweight crate, I think adding it to dependencies has no problem.

sile commented 6 years ago

According to the convention of sloggers, it may be better to specify the filter configuration as follows:

[[filter]]
type = "kv"  # Designates the type of this filter using "type" field
key="http_server"
values = ["get", "post"]
level="debug"

[[filter]]
type = "kv"
key="hw-subsystem"
values = ["camera"]
level="debug"

przygienda commented 6 years ago

pull request created. Didn't do the config part since you have to generate maps which is possible but I have no use for ...

przygienda commented 6 years ago

under works ... If anyone has cycle, I need AtomicSwitch refactored on my branch, KVFilter is done ...

dvtomas commented 6 years ago

@przygienda I've looked at your implementation as that's something I'm also going to need soon. If I understand right, it allows configuration of only one severity.

#[derive(Debug)]
pub struct FileLoggerBuilder {
    ...
    kvfilterparameters: Option<KVFilterParameters>,
}

#[derive(Debug)]
pub struct KVFilterParameters {
    pub severity: Severity,
    pub only_pass_any_on_all_keys: Option<KVFilterList>,
    pub always_suppress_any: Option<KVFilterList>,
}

That basically does not allow me to e.g.

set trace level for KV "hw-subsystem": "GPS"
debug level for "hw-subsystem": "Camera".

Is that a limitation of the original KVFilter, or just your way of configuring the builder? Would replacing kvfilterparameters: Option<KVFilterParameters> with kvfilterparameters: Vec<KVFilterParameters> be feasible?

przygienda commented 6 years ago

hey, interesting question. The problem is that slog does not have a concept of a "subsystem" so what you talk probably is just having slog.new(...) things each of them having different drain (and each drain its own KVFilter) ... So architecturally you already have what you need ...

slog suffers the usual problem of debug logging folded into reporting, namely that you have to evaluate the statement to filter it out most of time (debug statements)> that can have very massive performance implications and I solve it by wrapping my own macro taht checks level first with an if. Observe that LevelFilter does not do that, it evaluates the whole log first. There is a lazy eval on arguments in slog but I don't like that because 1) it only solves part of the problem 2) makes the slog statements even more cryptic IMO.

So, you'd have to give me an example what the vector means ...

On Tue, Sep 18, 2018 at 12:17 AM Tomas Dvorak notifications@github.com wrote:

@przygienda https://github.com/przygienda I've looked at your implementation as that's something I'm also going to need soon. If I understand right, it allows configuration of only one severity.

[derive(Debug)]pub struct FileLoggerBuilder {
...
kvfilterparameters: Option<KVFilterParameters>,
}

[derive(Debug)]pub struct KVFilterParameters {
pub severity: Severity,
pub only_pass_any_on_all_keys: Option<KVFilterList>,
pub always_suppress_any: Option<KVFilterList>,
}

That basically does not allow me to e.g.

set trace level for KV "hw-subsystem": "GPS"

debug level for "hw-subsystem": "Camera".

Is that a limitation of the original KVFilter, or just your way of configuring the builder? Would replacing kvfilterparameters: Option with kvfilterparameters: Vec be feasible?

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/sile/sloggers/issues/9#issuecomment-422282065, or mute the thread https://github.com/notifications/unsubscribe-auth/ABo0C37-JsgzbC-LLTCDZa1CR-Nl7D47ks5ucJ4HgaJpZM4RWKt2 .

przygienda commented 6 years ago

more specifically, I have my own keyword for subsystem and decorate all logs taht way and use the KVFilter to only_pass_any_on_all_keys to match against SUBSYTEMS => {any of the ones I want to log} ...

dvtomas commented 6 years ago

Yes, if I understand you well, I use something similar. Maybe you can help me, let me explain my setup.

I have a root logger composed of two drains: a File drain, and a terminal drain (like this: Logger::root(Duplicate::new(file_logger, terminal_logger).fuse(), o!())). Each of these drains is independently configured via sloggers. At various places I root_logger.new() new loggers with different values for the subsystem keys.

What I want to do is to have a set of KVFilters for the file drain, and another set of KVFilters for the terminal drain, both configured by a separate sloggers config file, that would allow me to

by default, log only INFO messages from all subsystems
when needed, usually for debugging purposes, be able to configure any subset of the subsystems to log DEBUG messages, and any other subset to log TRACE messages. Hence the need for different severities. Most of the times, only the File drain would be configured to do more verbose logging, but occasionally I'd like to also configure the Terminal drain.

Your other remark about debug logging is also very interesting, albeit probably a different topic. I've had this performance concerns on mind for a long time, but never really investigated deeply. If by lazy closure you mean FnValue, slog documentation basically doesn't say anything on the topic. This is something that is trivial to solve in languages with GC and closures (I've done it routinely in Scala), but seems to be a real bummer in Rust. Can you elaborate on how your macro works, and if it could help in my scenario (two drains, each with independently configured KV filters)? Or maybe it is something that would be better discussed outside this issue?

przygienda commented 6 years ago

Well, you can build two drains and feed them with one logger and stack on each of them different KVFilter. I think I did something like this.

As to my macro it's really primitive, it's

/// macro to early filter slog debug!

#[macro_export]
macro_rules! fast_filtered_debug(
    ($l:expr, $f:expr, #$tag:expr, $($args:tt)+) => {
        if $f >= slog::FilterLevel::Debug {
            slog_log! ( $l, slog::Level::Debug, $tag, $( $args )+ )
        }
    };
    ($l:expr, $f:expr, $($args:tt)+) => {
        if $f >= slog::FilterLevel::Debug {
            slog_log! ( $l, slog::Level::Debug, "", $( $args ) +)
        }
    };
);

where I drag a global variable along indicating what max log level the system/subsystem is at and that if's things out immediately ... Works very fine ...

I don't think scala or anything like this makes a difference, it's a problem in all languages I ever used.

dvtomas commented 6 years ago

As for the two drains, that is exactly what I was planning to do. And here I am with the original question: Would replacing kvfilterparameters: Option<KVFilterParameters> with kvfilterparameters: Vec<KVFilterParameters> make sense? I hope the motivation is clearer now, when I explained that I need some some levels to set to trace and some to debug, both on the same drain..

As for the closure, what I meant is that in GCed languages it is trivial to carry the computation to create the logging message to all drains, store it in some queues in case of an async channel etc, and discard it lazily when not needed with very little overhead. When it's more complicated to manage references, like in Rust, handling the computation also gets more complicated.

I'm actually on a thin ice with how the slog implementation works. Even after spending several hours reading the sources, I'm still don't really know how all the Records, Serializers, borrowed and owned KVs glue together. I think a high level overview on what structures get created and functions invoked when I do a info!(logger, "Msg"; "Hello" => "World"); would be nice. I think I'd like to use closures for the debug and trace statements, but this particular snippet worries me:

#[macro_use]
extern crate slog;
extern crate slog_async;
extern crate slog_term;

use std::fmt;
use slog::{Drain, FnValue, Level, Record};

struct Foo {
    value: &'static str
}

impl fmt::Debug for Foo {
    fn fmt(&self, f: &mut fmt::Formatter) -> Result<(), fmt::Error> {
        eprintln!("Foo::fmt = {:?}", self.value);
        write!(f, "{}", self.value)
    }
}

fn main() {
    let decorator = slog_term::TermDecorator::new().build();
    let drain = slog_term::FullFormat::new(decorator)
        .use_original_order()
        .build()
        .filter_level(Level::Debug)
        .fuse();
    let drain = slog_async::Async::new(drain).build().fuse();

    let log = slog::Logger::root(drain, o!("logger" => "root"));

    info!(log, "info"; "foo" => ?Foo{value: "info"});
    trace!(log, "trace"; "FnValue" => FnValue(|_ : &Record| format!("{:?}", Foo {value: "lazy trace"})));
}

I create a side-effecting Debug implementation, so I can see when the message formatter is invoked. In particular, I don't expect it to be invoked at all on the trace! line, since tracing is filtered out. But the output is:

Foo::fmt = "info"
Foo::fmt = "lazy trace"
Sep 19 07:41:45.804 INFO info, logger: root, foo: info

The FnValue got invoked even though that was not necessary. Very surprising!

Update

Ordering of Async and LevelFilter matters, see the explanation here: https://github.com/slog-rs/slog/issues/186#issuecomment-422942375

przygienda commented 6 years ago

I still don't understand what the array would represent. You have two KVFilters, one per drain, please give me a snippet of code what you're trying ...

dvtomas commented 6 years ago

Let's assume I have just one drain (say the File drain), and I want to put a filter on that that would

pass all records with ("subsystem": "A1" || "subsystem": "A2") && level at least trace
pass all records with (subsystem": "B1" || "subsystem": "B2") && level at least debug
pass all records with level at least info
reject all other records

Is that possible to do with KVFilter (or several KVFilters and maybe a LevelFilter)? Maybe it is not possible, I haven't used KVFilter yet. However, if it is possible, how do I use the sloggers extensions you implemented to configure and build such filter(s)?

przygienda commented 6 years ago

you put one KVfilter with info on it and you put individual LevelFilters with according levels under it on the Drains ...

On Wed, Sep 19, 2018 at 12:17 AM Tomas Dvorak notifications@github.com wrote:

Let's assume I have just one drain (say the File drain), and I want to put a filter on that that would

pass all records with "subsystem": "A1" or "subsystem": "A2" and level at least trace

pass all records with "subsystem": "B1" or "subsystem": "B2" and level at least debug

pass all records with level at least info

reject all other records

Is that possible to do with KVFilter (or several KVFilters and maybe a LevelFilter)? Maybe it is not possible, I haven't used KVFilter yet. However, if it is possible, how do I use the sloggers extensions you implemented to configure and build such filter(s)?

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/sile/sloggers/issues/9#issuecomment-422685244, or mute the thread https://github.com/notifications/unsubscribe-auth/ABo0Cwjx-JtiL0wqn-sffTBWmZ1OhN1Zks5uce9ygaJpZM4RWKt2 .

dvtomas commented 6 years ago

Well, I slept on it, and this is actually a good idea. I was too stuck on the KVFilter mindset, I actually started to implement my own variation of KVFilter. Just for inspiration, this is what I'll probably end up doing:

I will not use a KVFilter at all. I do not need to have logging levels based on WHAT get's logged (e.g. a session with an individual user or IP address), all I need to do is to set logging levels based on a particular logger that gets created with e.g. log.new(o!("subsystem" => "example").

What I will do is (it will probably be more complicated than this, but this is the the core idea) replace all calls to log.new(o!("subsystem" => "example") with some custom function, create_sublog(log: &Logger, subsystem: String, global_logging_settings: HashMap<String, Level>).

create_sublog will

create the new log
add a LevelFilter to it based on the subsystem and global_logging_settings
in debug build, append a subsystem = {level} to a file logging_template.cfg. This way, when I run the program, it will create a configuration template with all the subloggers enumerated (this of course depends on all the subloggers being created during the execution of the program, but that is a reasonable expectation in my case).

I think this will work nicely for me, thank you.

przygienda commented 6 years ago

ok, yepp, I think KVFilter is meant for a different use. It's basically slicing a subset of log messages out a single logger. That is very common and very important on complex systems where the amount of logging is overwhelming and often completely melts the system if you try to see everything ...

On Wed, Sep 19, 2018 at 10:35 PM Tomas Dvorak notifications@github.com wrote:

Well, I slept on it, and this is actually a good idea. I was too stuck on the KVFilter mindset, I actually started to implement my own variation of KVFilter. Just for inspiration, this is what I'll probably end up doing:

I will not use a KVFilter at all. I do not need to have logging levels based on WHAT get's logged (e.g. a session with an individual user or IP address), all I need to do is to set logging levels based on a particular logger that gets created with e.g. log.new(o!("subsystem" => "example").

What I will do is (it will probably be more complicated than this, but this is the the core idea) replace all calls to log.new(o!("subsystem" => "example") with some custom function, create_sublog(log: &Logger, subsystem: String, global_logging_settings: HashMap<String, Level>).

create_sublog will

create the new log

add a LevelFilter to it based on the subsystem and global_logging_settings

in debug build, append a subsystem = {level} to a file logging_template.cfg. This way, when I run the program, it will create a configuration template with all the subloggers enumerated (this of course depends on all the subloggers being created during the execution of the program, but that is a reasonable expectation in my case).

I think this will work nicely for me, thank you.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/sile/sloggers/issues/9#issuecomment-423045733, or mute the thread https://github.com/notifications/unsubscribe-auth/ABo0C11PAxN49cZwTppr14yB2gmDoogNks5ucykfgaJpZM4RWKt2 .

przygienda commented 6 years ago

This should probably be closed now ...

dvtomas commented 6 years ago

In the end I've decided that just putting level filters on sublogs is not such a great idea. Correctly resolving the filters configuration wouldn't be so easy, in order to work properly, parent loggers would have to set the filters according to their children level settings. I decided to rewrite KVFilter to be more generic and support both your and mine scenarios. You can see the preliminary result after a couple days work on it here: https://github.com/dvtomas/kvfilter/blob/complete-rewrite/src/lib.rs

At the bottom you can see test_complex_example - that is what KVFilter does now, and test_complex_example_2 - that is what I want KVFilter to do.

The new KVFilter configuration is fully (de)serializable with Serde. That could easily solve the original intent of this issue. However, I think I'll start writing the logger configuration in JSON instead of TOML, the filters recursive representation in TOML could get unwieldy soon.

I'm curious about the opinions on the new KVFilter.

dvtomas commented 6 years ago

FYI, I've added preliminary support for the new KVFilter to sloggers, in this branch: https://github.com/dvtomas/sloggers/tree/new-kvfilter

Of course I'm still not sure if the new KVFilter will be accepted as-is, or even at all. I'll see..

sile / sloggers

Add support for slog_kvfilter #9

[derive(Debug)]pub struct FileLoggerBuilder {

[derive(Debug)]pub struct KVFilterParameters {

Update