-
Notifications
You must be signed in to change notification settings - Fork 256
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Structured Logging #149
Comments
Really? Awesome. Is that planned to be added before |
The thought I had in the meeting was something like this: info!("..."; MeaningfulType(information), PossiblyAnother(something_else)); where the currently selected logging implementation receives anything that matches its associated type, and any other types do nothing. Key-value style structured logging in this paradigm may look something like this, where the info!("..."; kv!("a" => a, "b" => b)); EDIT: or obviously it could provide its own macros that replace the ones in log: info!("..."; "a" => a, "b" => b); |
@dpc that's the current intention, yeah, preparing this for the 1.0 release. We'd probably do it in 0.3 if we could, but it's unlikely to be possible without breaking changes! We're of course very eager to hear about everything you've done with |
I will be happy to share my perspective and experiences during the discussion. Personally, I would be very happy to see as many features from The whole feature is implemented in Edit: Also, reading the documentation of https://docs.rs/slog/2.0.5/slog/macro.log.html , might give a good overview of features supported. Eg. it's possibe to use just |
When we do add structured logging, there's one question I'm wondering about: what do we encourage users to use? Binary crates choosing either to go full-formatting (like current I mean having a library output debug information in structured logging will give the end reader more flexibility, but I'm guessing it would also add a bit more overhead as well. If all a binary crate wants is a console stream of readable log messages, is it best to construct the additional structured log records and then just use a default conversion to a string? I'm also curious what the best practices for this in |
Good question. I'm aware that not everyone buys into the whole structured logging concept. Especially in It would be useful to check experiences of any other programming language community. I'm not aware of any languages that have first-class, core-encouraged, structured logging support, but maybe there are some. IMO, if structural logging is to be supported, then it should be encouraged, since as far as I can see it is clearly better. Even if you just log a stream on a console, doesn't screenshot on https://github.com/slog-rs/slog look better than a plain wall of text? Without structured logging, you can only distinguish between basics: logging level, timestamp and message, etc. With structured logging, there is much more flexibility. And libraries can't decide for all applications using them, what kind of logging should they need so they should default to structured, as it can cheaply and gracefully be downgraded to plain line of text. The performance different is negligible. In |
Thanks for going over that! I think initially I was a bit worried that adding complexity to The console logging does look nice! I mean, I would think it'd be nicer with data "inline" with the message, but then that would sacrifice all the rest of the flexibility. To me,
looks better than
... but I imagine having ecosystem-wide structured logging would be excellent for larger applications. The coloring available when data is separated like that isn't too bad either! I think my ideal logging scheme would be something like In any case, thanks for that! |
@dtolnay: I propose a hopefully leaner/less magical implementation than making KV part of a macro as now in the |
I just wanted to highlight one of the features I like best about For example I have a Hyper Eventually the application accesses the logger and logs something about the
What is interesting however is that prior to this the logger has been extended by some other code (that I may or may not know about):
The output (assuming JSON formatter) is then roughly:
If I also added some external code to do authentication it might end up as:
I understand that passing a |
@bradleybeddoes I believe the part you're describing is called "contextual logging". I'm not sure if we should open another issue or consider it a part of this issue. |
As long as it's possible to construct a |
I probably don't understand what does "structured logging" mean but seems like people assume that logging automatically means terminal or streaming to a file and then reading that file, so you need it to look nice for that use-case. My personal interest(I guess I'm selfish) is to keep the cost of the logger as low as possible because in my case(a lot of services on an embedded device, all sending logs over the network), people send thousands of logs per second(actually, this is the amount of logs coming from the device, not from every application separately) and I can't afford adding overhead. More info about DLT, here: https://at.projects.genivi.org/wiki/display/PROJ/About+DLT-Transport |
In .NET we have serilog which uses a standard message templating syntax for structured logging. @nblumhardt and I spent some time a while ago exploring a similar design for Rust. The idea is to log both a textual log message template along with the individual properties and additional context that make up a message. It's up to the particular sink to decide how it consumes the template and the properties, maybe by substituting properties in, composing a new object with a property containing the message, whatever. Libraries don't care where their logs go. I'll admit I haven't spent a lot of time digging into the state of structured logging in Rust or the API |
One of the things we explored with emit was keeping very close to the API of the I.e. here's a typical info!("Hello, {}!", env::var("USERNAME").unwrap()); And here's the structured extension along the lines of info!("Hello, {}!", user: env::var("USERNAME").unwrap()); The two events would produce exactly the same textual output, but by naming the Keeping a smooth continuum from completely unstructured, to fully-structured, log events might be preferable to splitting the API into two unrelated subsets, if it could be achieved in a non-breaking way :-) |
How is the performance of such structured logging proposals? "Message Templates" seems like it will involve string parsing/manipulations. Eg. It looks to me that The way structured logging is done in |
@dpc You're absolutely right that's an important point. And we expect a core Rust crate to cater to those use cases where performance is paramount. But how you capture properties is more of an implementation detail, whether it's a hash map or some kind of linked list or something else. I think we both agree that the latency of logging from a caller's perspective should be absolutely minimal, and the reality in either case is that a sink has the freedom to consume the structured log however it needs for its eventual destination. The main thing I'd like to maintain is not having to pass a logger into the log calls, or have to carry a logger around in libraries for the sake of structured logging. I think it's still important to support that case, but in my experience it's been most helpful to grab the ambient logger and enrich it with some additional state as necessary rather than chain a logger throughout your application. |
I think it would be awesome if we could get something like Perhaps with a proc-macro-hack, or maybe even without, could the log!() macro be made to store a temporary for each argument, then put the arg in both a stack-allocated array of A vec or hashmap could then be allocated by the logging backend if it needed to send the arguments to another thread, or any other permanent storage. |
It's pretty straightforward to turn something like I would very much like to keep the "normal" logging path allocation free, and that shouldn't be too much harder to make happen with some structured logging. |
This is a part of "contextual logging", and is orthogonal to structured logging provided by slog. One can use I was mostly wondering about:
from https://messagetemplates.org/. It is a nice idea, but I wonder how hard it will be to generate static information at compile time, using stable-Rust macros.
What will be the type of it? I was doing something like that in slog v1: Now that I looked at https://messagetemplates.org/, I kind of wish I did it as so in slog. Though I still don't know how to write a macro for it. |
For basic logging, this is already somewhat supported with This works in today's log:
http://play.integer32.com/?gist=09caba59aeed61eb13ec7c3261b7c97c&version=stable |
Hmmm... I liked the fact that one does not have to repeat itself in |
Also, how to support "additional" keyvalues? Eg.
The Somehow the macro would have to make distinction between the values used in the text message, and addition ones, as
Also, what are the preferences for the delimiter between key and value? Slog uses
be fine with everyone? Or are there any alternative preferences/ideas? |
As far as I can tell, neither Regarding the logging macro syntax bikeshedding, I quite like keeping To summarise, I like: info!("{} {msg}", "Hello", msg="world!"; k: v); |
A lot of people asked for structured types in slog. Sadly it has many challenges. I didn't feel up to the task and just left it out. I think it's a complex subject, and maybe we could use a different github issue so we keep this one focused on the core structured logging. |
At first I didn't really like the syntax of separating replaceable properties from other properties, because I see the message as just a view over the properties. But thinking about it, rejecting logs at compile time with messages that aren't properly replaceable sounds useful. |
Provides extensive logging across the project, especially at the TRACE level. Currently also tracking rust-lang/log#149. Keen to have Gotham move to structured logging as soon as practical.
What's the status here? Anything that can be done to move this forward? |
Jumping in here because I have interest in this, and to throw in some extra thoughts... I'm a big fan of just being able to log a single struct as one value and not having to write out all the fields each time. In fact, at my company we're using quite successfully an extension we've written for slog (https://github.com/slog-rs/extlog) which allows defining logs entirely as objects, rather than "string + KV data". It would be great if the log crate could do something similar - at least as far as having the Something like: /// Define the log.
#[derive(LogObject)]
#[LogDetails(message = "An event has happened", level="info")]
pub struct MyAwesomeLog {
pub name: String,
pub count: u32
}
// Then later...
log!(MyAwesomeLog { name: "my_user".to_string(), count: 42 }); This is equivalent to writing |
@Thomasdezeeuw This does still have the problem that I have a different opinion about leaning on What are some concrete downsides you can see from using |
@mthebridge Neat! I can see why some folks would find it appealing to log that way. I think we could achieve something similar in |
@KodrAus I don't really need the actual type for the value, As for the depency on I think that the API should remain small, yet flexible, so that @mthebridge I like the idea, but maybe that could be done in another crate? Like |
@Thomasdezeeuw Oh, yes - I'm not saying this should be in the core @KodrAus Thanks, I wasn't aware of proposals to change macro imports - I assume this is rust-lang/rust#35896? Overwriting the log macro feels a bit hokey, but I guess if it works then that solves my concerns! |
@Thomasdezeeuw Stability is a valid concern. However I'm confident there's no way As for stability itself, There's no concrete answer to the hypothetical scenario where But those are just my thoughts. I'm sure @dtolnay has plenty about |
I went back and had another look at the last API I was playing with based on @dpc's comment about control flow and rejigged it so keys and values are passed in to the I retained the Overall, the public API could look something like this: // --- RecordBuilder
impl RecordBuilder {
fn key_values(&mut self, kvs: &'a dyn KeyValues) -> &mut RecordBuilder<'a>;
}
// --- Record
impl Record {
fn key_values(&self) -> &dyn KeyValues;
fn to_builder(&self) -> RecordBuilder;
}
// --- Visitor
trait Visitor {
fn visit_pair(&mut self, k: Key, v: Value);
}
impl<'a, T: ?Sized> Visitor for &'a mut T where
T: Visitor
{}
// --- KeyValues
trait KeyValues {
fn visit(&self, visitor: &mut dyn Visitor);
}
impl<'a, T: ?Sized> KeyValues for &'a T where
T: KeyValues
{}
impl<KV> KeyValues for [KV] where
KV: KeyValue
{}
#[cfg(feature = "std")]
impl<KV> KeyValues for Vec<KV> where
KV: KeyValue
{}
#[cfg(feature = "std")]
impl<K, V> KeyValues for BTreeMap<K, V> where
for<'a> (&'a K, &'a V): KeyValue
{}
#[cfg(feature = "std")]
impl<K, V> KeyValues for HashMap<K, V> where
for<'a> (&'a K, &'a V): KeyValue,
K: Eq + Hash
{}
// --- KeyValue
trait KeyValue {
fn visit(&self, visitor: &mut dyn Visitor);
}
impl<'a, T: ?Sized> KeyValue for &'a T where
T: KeyValue
{}
impl<K, V> KeyValue for (K, V) where
K: ToKey,
V: ToValue
{}
// --- ToKey
trait ToKey {
fn to_key(&self) -> Key;
}
impl<'a> ToKey for &'a dyn ToKey {}
impl<T> ToKey for T where
T: AsRef<str>
{}
// --- ToValue
trait ToValue {
fn to_value(&self) -> Value;
}
impl<'a> ToValue for &'a dyn ToValue {}
impl<T> ToValue for T where
T: serde::Serialize + Display
{}
// --- Key
struct Key<'a>:
ToKey +
serde::Serialize +
Display +
Clone +
PartialEq +
Eq +
PartialOrd +
Ord +
Hash +
AsRef<str> +
Borrow<str>;
impl<'a> Key<'a> {
fn from_str(&'a str) -> Self;
fn as_str(&self) -> &str;
}
// --- Value
struct Value<'a>:
ToValue +
serde::Serialize +
Clone;
impl<'a> Value<'a> {
fn new(&'a impl serde::Serialize + Display) -> Self;
fn from_display(&'a impl Display) -> Self;
fn from_serde(&'a impl serde::Serialize) -> Self;
} I was thinking it might be good to put together some kind of an RFC document for structured logging including the various alternatives that have been proposed here and What do you all think? |
Great work pushing it all forward. I like this API. About I am lacking time to maintain a separate ecosystem for Rust logging, and my family is going to get bigger soon, so I will have even less of it. The reason why If I would be very happy if The thing with contextual logging is that logging records with context carry a lot of data. For asynchronous logging, serializing them on the current thread is going to be slow. That is why in Other than that, I think the nice part about I think you should push forward and after getting some opionions of maintainers of BTW. I had some time for sketching and I've created a branch "how would I like to improve slog in next major version". https://github.com/slog-rs/slog/blob/v3/src/lib.rs Just in case you're curious. It matches almost 1 to 1 with your API, and some small differences are mostly to support the "contextual" logging. |
We've just merged an RFC for an implementation 🎉 I'll start working towards landing some of the key pieces of that RFC shortly. |
I’ve opened #328 to track the actual implementation of structured logging, since I think it’ll be easier for folks to get up to speed on where things are at with a new implementation-focused tracking issue. There’s a lot of history and cross-linkage here (and possibly a bunch of people subscribed) but now that we’ve shifted gears if there’s anyone interested in following along or contributing to the implementation then I think #328 is the place to go. There’s enough on |
One of the major points of discussion during the log evaluation was structured logging, specifically the
log
crate's relation toslog
. In the review we ended up concluding that there's no reason to not add structured logging to thelog
crate and it'd be awesome to unify the slog/log ecosystems!This issue is intended to serve as a tracking issue for concerns and ideas related to this. For example the specific APIs the
log
crate would have, how this would relate toslog
, migration stories, etc.The text was updated successfully, but these errors were encountered: