Structured Logging #149
Labels
No labels
bug
duplicate
easy
enhancement
help wanted
invalid
question
rfc
structured-logging
wontfix
No milestone
No assignees
1 participant
Notifications
Due date
No due date set.
Dependencies
No dependencies set
Reference
gh-rust-lang/log#149
Loading…
Reference in a new issue
No description provided.
Delete branch "%!s()"
Deleting a branch is permanent. Although the deleted branch may continue to exist for a short time before it actually gets removed, it CANNOT be undone in most cases. Continue?
One of the major points of discussion during the log evaluation was structured logging, specifically the
logcrate's relation toslog. In the review we ended up concluding that there's no reason to not add structured logging to thelogcrate 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
logcrate would have, how this would relate toslog, migration stories, etc.Really? Awesome. Is that planned to be added before
log 1.0.0release?The thought I had in the meeting was something like this:
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
kvmacro is provided by the structured logging library to construct the appropriate type:EDIT: or obviously it could provide its own macros that replace the ones in log:
@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
slogand the best way to make progress on this. Want to make sure you're kept very closely in the loop!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
slogported tologsoslogcould just reuselog, or even be rendered completely unnecessary. I've also pingedslogusers in case they are interested - they probably know better than me what do they look for in structured logging.The whole feature is implemented in
slog, and of course, I tried to make it as good as I could have imagined, so my initial point of view is: just take a look at https://docs.rs/slog/2.0.5/slog/trait.KV.html and https://docs.rs/slog/2.0.5/slog/trait.Serializer.html , and potentially otherslogpieces, and use it as a starting point for discussion. TheKV+Serializerare loosely mimickingserde, just simplified (eg. no sequences support).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
somevalin place of"k" => valifsomevalimplementsKVso thatsomevarcan supply it's own key(s) (useful for logging structs)); or"k" => %vifvimplementsDisplayetc.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
log) or full-data is not a problem, but if we continue to support both, what should libraries choose?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
slogcurrently are, if that would be reasonable to expand on? I mean, so far my actual usage ofloghas been a leveledprintln!()replacement with the extra bonus that I get debug messages from my dependencies as well. Not that this has to be answered here - I should probably just go read the documentation - but it might be useful context for adding an implementation to thelogcrate too!Good question. I'm aware that not everyone buys into the whole structured logging concept. Especially in
slogwhere more "unusual" features are bundled together, people don't initially see the whole value proposition. Most people are used to "there is one global logger and I give lines of texts" logging and ask "why all this hassle?". I myself became "a believer" once I was working on a heavy-duty production service written in Go, where all the data was logged to json, collected to elastic search cluster where business analytics and monitoring was performed on it.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
slogall structured logging key-value are just one additional pointer toKVobject data. If you doinfo!("received number: {}", n)then there will be one "formatting to string" done for you. If you doinfo!("received"; "number" => n);and then write it to stream, there will also be one pass of "formatting to string" done for you. As far as I can tell, any logging performance considerations should be mostly: avoid copying and allocation, not doing anything until needed, preparing as much as possible during compilation (staticetc.) and asynchronous logging (making sure passing logging data to another thread is cheap).Thanks for going over that!
I think initially I was a bit worried that adding complexity to
logwould scare new library authors away from adding logging into their libraries, but I think it won't be too bad.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
info!("received number: {number}", number => n), with data both separated out into query-able structured records, and placed inline with the formatting - but that'd probably be a lot of work and complexity in teaching for little overall gain.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
slogcrate. What do you think about the logging function taking a single value-argument of aSerializetype? The deeper structure or representation of a record is then left to the programmer. It would be quite easy to declare a wrapper type for emitting the logging record as some sort of KV-dictionary. The advantage is that any logging record has a meaningful, possibly varying type. And of course the less magic thing, new developers just starting to use logging would not have to learn the intricacies of another set of macros.I just wanted to highlight one of the features I like best about
slogwhich is simply the ability to add structure to the resulting log message as different parts of the application get involved.For example I have a Hyper
Service. EachRequestis given a unique logger instance early on in thecallfunction (a simple clone of a root logger, which is cheap inslog).Eventually the application accesses the logger and logs something about the
Requestit has been working on, such as: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
loggerinstance all over the place may seem clunky to some folks but if we can figure a way to maintain this functionality there are a lot of nice benefits that can be gained.@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
Recordvia the public API (which we're going to support), a contextual logging library can be built on top of log without too much trouble I don't think.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.
Here is the project I'm thinking about here(a bit inactive, sry...): https://github.com/lilianmoraru/dlt-rs
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
logexposes besides it's macros for a long time so will go and catch up.One of the things we explored with emit was keeping very close to the API of the
logcrate - just adding a little bit of structured-logging-sauce on top :-)I.e. here's a typical
logevent:And here's the structured extension along the lines of
emit:The two events would produce exactly the same textual output, but by naming the
userparameter, this would also be available as structured data attached to the event, if the log destination supported it.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
emitis dynamically allocatingHashMapevery time it logs anything: https://github.com/emit-rs/emit/blob/master/src/lib.rs#L144 . Might be OK for languages that are generally not very performant and overallocate all over the place, but probably in Rust niche, it can be a problem.The way structured logging is done in
slogis very performant, with ability to very quickly offload any formatting and output to different thread(s), with minimal work done by the current thread.@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
emit's syntax working for this, glad you mentioned that nblumhardt.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
&[(&'static str, &Display)]and pass it onto format_args!()?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
{foo: some_variable, bar: "some_literal"}into&[("foo", &some_variable), ("bar", &"some_literal")]in a normal macro-rules macro.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
slog-scopeand not worry aboutLoggerobject if so inclined.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:
&[&'static str, &Value]whereValuewas a trait. The trait was so that users can implement it for other types. But then I switched in slog v2 to just&KeyValuePairswhereKeyValuePairsis a trait, since it had many benefits: it is possible to implementKeyValuePairsfor any type (arrays, tuple, heterogeneous list, structs, etc.). Key can be generated at runtime, supporting lazy values etc. The common case is of courseimpl KeyValuePairs for [(&'static str, T)]. SinceKeyValuePairsprovides potentially multiple key-value pairs, it can control order of pairs, orimpl KeyValuePairsfor combination of contexts etc.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.
@dpc
For basic logging, this is already somewhat supported with
format_args!(). Any custom macro would just have to send arguments to that correctly, and then also be able to use them to create an array.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
log("User {username} logged in from {ip_address}", username, ipAddress)but maybe it is even better, since it's not position dependent.Also, how to support "additional" keyvalues? Eg.
The
request_idis assigned to the key-value pairs, but is not actually used in textual message itself. Sometimes the number of additional data might be quite big, and not everything is neccessary in the text information - some might be mostly useful for robotos.Somehow the macro would have to make distinction between the values used in the text message, and addition ones, as
format_args!()complains in any argument was not used (rightly so). Could be eg. additional separator.Also, what are the preferences for the delimiter between key and value? Slog uses
=>but it is kind of heavy. Would:be fine with everyone? Or are there any alternative preferences/ideas?
As far as I can tell, neither
emitorslogseem to support arbitrary types as structured values (see emit's Value enum, slog's Serializer trait). I found myself wanting to log e.g. a UserContext struct but could not do so. I'd be very happy to see support for any value with a serde::Serializable implementation, or some similar trait. Of course as a workaround you can convert any struct to JSON and store that.Regarding the logging macro syntax bikeshedding, I quite like keeping
format_args!as a subset, so using=between key and value for string formatting. I slightly prefer;over,between string formatting and structured arguments. I quite like:between key and value for the structured arguments, to match the struct literal syntax, but=>and=are also OK.To summarise, I like:
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.
What's the status here?
Anything that can be done to move this forward?
The next step would be to design the API. In particular, we need to figure out what the interface to the structured data is. We want the logging codepath to be allocation-free, so it'll be some object-safe trait. It might end up looking a bit like rustc-serialize's
Encodable? We also need to figure out what the macro syntax would look like.slogalso supports adding environment to the current logger, even if the logging statement is unaware of it. This way, you can e.g. log stuff from your packet parsing routine, but have a source IP address annotated because the surrounding code added it to the environment. https://github.com/slog-rs/slog/issues/124 is an issue aboutslogseemingly needing allocations to do that (I lost track of that issue), but it would be nice if thelogcrate could do the same without any allocation overhead.This way you can add annotation to log statements that aren't even in your library. (I don't remember the exact syntax
slogused, this example was just made up.)It would be great to have the following optional notation
This could men the same as
See also https://github.com/rust-lang/rfcs/pull/2173 for an RFC about "A quick dbg macro"
BTW. Structured types have been added to slog behind a feature flag. https://docs.rs/slog/2.1.1/slog/trait.Serializer.html#method.emit_serde . I'm not sure if that's the best way to do it, but since people continuously asked about it, we agreed on some design and here it is.
Is there anything I can do to help with this?
@nielsle I have landed this in
slog's master.To try get the ball rolling here again I've put together a rough but 'functional' strawman API for structured logging using
log::Record. Accessing properties to output inenv_loggerlooks like this. Also see an example of treatingLogs like a pipeline to add properties to a log from some context before passing it along. Point is we don't need to change much inlogitself to get this all working, and theLogtrait itself doesn't need to change.You'll have to ignore all the mess around features (I tromped all over the
no_stdsupport and didn't bother making it work), and the fact that properties are driven byserderather than some internal trait, and the fact that I haven't thought about the macros.But this does give us an idea of how we can support arbitrary properties that can be iterated through, serialized or have their values inspected without having to allocate for them.
The gist of it is:
KeyValuestrait that supports iteration by threading around a commonKeytype. The trait is implemented for slices,Vecs andBTreeMapso they can be used as a source for properties. It could be simpler without supporting iteration, but it does mean properties can be inspected without just being an opaque value to pass to aSerializer. Iteration is also going to be slower than your typical iteratorSerializetrait (just usingerased_serde::Serialize)Serializer(maybe theas_*methods on properties makes this confusing)Our
logmacros would expand to something like:And other consumers with non-static data can do something like:
Inspecting properties looks like:
What do you all think about the idea of iterating over and inspecting properties at the expense of muddying the waters around serialization? Should we try put together our own
Serialize-like trait, or are we happy to lean onserde(personally I'm happy to lean onserde)? ShouldRecorditself be serializable?@KodrAus I took a look and it looks a bit complex: there is a lot of types, some traits, and enums.
I'll give
slogapproach differences, with some experiences and explanation why it is the way it is.In
slogany structured data is just something that implementsKV.KVrepresents zero, one or manykey-valuepairs.KVhas to know how to do one thing only: serialize itself to aSerializergiven to it. ThisSerializeris very much likeserdeone, except stripped a lot. At the timeserdewasn't s mature, etc. I might have usederased_serde::Serializernow).Comparing to your version, there is no
Properties,Property,Entry,KeyValues. All of it is justKV, and what exactly is implementingKVis not very important. The API cares only about theKV.You can implement
KVfor anything and users can extend it as they see fit, eg. to use their own data to serialize itself as a list of key-value pairs .In
slogif you want to eg. iterate and locate a specific key-value, you just write a type that implements theSerializer, ignore what you are not interested in and act on what you are interested. It's effectively an iteration. except:with-like functions https://github.com/rust-lang-nursery/log/compare/master...KodrAus:feat/structured?expand=1#diff-9a1fcf6f57a3174fec8999d891036ff0R30 and serializing upfrontchainedin your version it's posible to prepend, but if you wanted to do append (add to the other side) it wouldn't be possible/efficient. Inslogyou can have a type agregating 2 innerKVvalues, and depending on the need serialize them in the requred order. Inslogthe order ofKVs is actually important because of supporting contextual logging - the values that were created first, are more of "global" context.Serializermethods.I agree with @dpc, it does seems rather complicated. It also adds a hard dependency on serde and erased_serde. In particular, erased_serde doesn't have a 1.0 release yet, so following the API Guidelines it can't be a public dependency if log is stabilized.
Sorry I haven't been following the thread closely but -- we should be able to get erased-serde to 1.0 if it comes down to that.
To be clear, I think that using serde for serialization is a good idea. I just wonder if there is a way it could be behind a feature flag. But I haven't been able to think of an API where such a feature flag could be additive, and I don't know if there are enough projects that need log but not serde to make it worth it.
Yes, I think there's definitely room to improve!
The
KVtrait is indeed very general, but in my opinion that can also make it trickier to work with. If you want to look at your structured properties then you need to create aSerializer. If you wanted some nice way to iterate over your structured properties I think you would need some similar machinery to what I wrote (which is also very rough 😅). So I've tried to make an intentionally different set of tradeoffs here toslogto give you a bit more out-of-the-box just to see how that works out.It's possible that the
KV+SerializerAPI is all we need and friendlier ways to interact with properties can be bolted on in other ways if anyone wants them. Like @dpc mentioned,KVcan handle things like ordering in addition to everything else.One thing I do like is bundling all your structured data onto the
Recorditself.That's true! It's just an experiment so we can debate the virtues of different ways to capture structured data so I wasn't worried about that yet. I do like the idea of leveraging
serdeif we can though.Ok, so based on the input from @dpc I've taken a different approach with this, with something much closer to
slog'sKVAPI.API
Value: which is a re-export oferased_serde::Serialize(with some hacked inno_stdsupport)KeyValue: which basically just lets us be generic of(K, V)and&(K, V)KeyValues: which is basically the same asslog::KV. It can be serialized using aSerializer. It's job is to pass each of itsKeyValues to that serializerSerializer: which accepts a singleKeyValueand serializes itwith some implementations:
KeyValuefor(K: AsRef<str>, V: Serialize)KeyValuesfor&T: IntoIterator<Item: KeyValue>. So types likeVec<(String, serde_json::Value)>,HashMap<&'static str, u64>etc are allKeyValuesSerializerforserde::ser::SerializeMapThe
&T: IntoIteratorblanket implementation isn't great though. Should we just not provide one and let users implement it themselves?There's also a
Propertiesstruct. I thought this was better than exposing aKeyValuestrait object directly fromRecordso we can add methods and other implementations to it easily.PropertiesimplementsKeyValuesandserde::Serialize.The contract of
Propertiesis that keys aren't guaranteed to be unique or in any particular order.no_stdI've managed to get this working with a few degrees of
no_stdsupport:std: structured properties are supportedcore + alloc: structured properties are supportedcore: structured properties are not supported (the currentlogAPI is still though)Implementation
This is still very rough, like the last one, but I have an implementation of this for:
logshowing how structured properties are collected (still no macros)env_loggershowing how structured properties can be written to some outputlog-enrichshowing how additional properties can be pushed onto a log record, treatingLoglike a pipelineAll together that ends up looking a bit like this:
This shows that we can rely on
erased-serdeif we're willing to accept at leastalloc. What do you all think of this approach?If we did something like this I think we'd need to at least require the
allocfeature by default, but that currently would requirenightly. I've been hoping the talk about refactoringstdaround the portability lint might make that whole experience nicer.@KodrAus I like it. It's even simpler than
slog's one since you based it onserde-erasedfrom ground up.Some comments
Propertiesmight be unnecessary? It could be namedChainedKeyValuesin the first place, and it doesn't look to me likelogactually strictly needs it.Recordcould store justkvs : &KeyValues, I think.Since
KeyValuesis a trait that is opened for anyone to implement, there can be many strategies to implement it. Eg. inslogI relied heavily on composing types with:https://docs.rs/slog/2.1.1/slog/trait.KV.html#impl-KV-2
to build a heterogeneous list, that (the hope is) will be compiled to optimized code through monomorphization, avoiding the
if let Some(...) = self.parentruntime check. Hopefully, this does not create too much "Monomorphization Bloat" etc. but the point is - if there's no need forlogto make that decision, it might be better to leave that type out oflogitself. Unless there's a clear benefit of establishing such a common primitive there, of course.It might be worth to consider
Send/Synctraits right now too. Efficient async logging can't be achived, if the API does not make preparations for it.slogrelies heavily on being able to push long chains ofKeyValues("context") to another thread without copying or serializing them on a current thread. It does it through https://docs.rs/slog/2.1.1/slog/trait.SendSyncRefUnwindSafeKV.html . I don't know if it's possible/worth of adding it tolog, but I think it's worth considering right now.I guess
Recordwould have to keep bothkvs : &KeyValuesand something similiar tosend_kvs : KeyValues + Send + Sync + etc.. andSerializerwould have to have a method that retains+ Send + Syncso the underlying implementation can use that fact to avoid doing work on the current thread. It's all a bit of a hassle, since things get duplicated: one version is for potentially non-Send KeyValues, one for SendSync KeyValues.But it's a significant performance difference in
slogif you look atasyncbenchmarks at https://github.com/slog-rs/slog/wiki/Bench-log (4 first benches) .10_owmeans 10 owned KeyValues (owned, implies SendSync) actually passed as one compositeSendSyncKeyValue. It take no additional time as their number grows, while10_br(10 borrowed, non-Send KeyValues) adds ~250ns because each value has to be serialized first, stored together, then passed to another thread. Seeslog-async` for short implementation.Thanks for the input @dpc!
Yeh, we might not really need
Properties. Right now it's filling a few roles:KeyValues. We might want methods likecount(&self) -> usizeorcollect_into<T: Extend<U>, U: KeyValue>(&self, &mut T)that are convenient, but might not make sense onKeyValuesitself. Maybe they do though. TheSend + Syncquestion might fall into that categoryserde::Serialize. Since theSerializerwe define here is more likeserde::ser::SerializeMap, so it needs some outer wrapper around theKeyValuesthat lets them write into a mapno_stdcase where there's no allocatorI think all of these could be designed around though. I agree we'll definitely need to come to some conclusion about
Send + Syncsooner rather.Another question I haven't thought about yet is error handling. Right now all the properties traits are infallible, which is probably not ideal. It might be ok since
Logis infallible, but we should think about it.@KodrAus
You could add
countintotrait KeyValuesExtor directly intoKeyValueswith some default impl.I've missed the error handling. Yeah, in
slogthere is a https://docs.rs/slog/2.1.1/slog/enum.Error.html , but I always thought it's incomplete. I'd probably replaceOtherwithfailure::Errornow.Hi everyone! I found some time to revisit this thread and thought I'd share the latest iteration I've been exploring. I don't want to build a sandcastle so as always am keen for any input!
Strawman
logAPINOTE: I've used some recent Rust features in my strawman implementation like
impl Traitanddyn Trait. That's just because it's convenient. We don't actually need to bump the minimum version to make any of this work.Some thoughts
I thought I'd share a few of the things I've tried to keep in mind when exploring the ways we could do structured logging in
logfirst.I'd like to be able to find a design for structured logging here that doesn't require a major breaking change to
log. So the structured logging implementation I'm exploring is one that fits in the current design of thelogcrate.Right now,
logis your entrypoint, it's only got what you need to capture the input given tolog!macros and have that input handled by some registered callback. More sophisticated pipelining of log records by composing handlers together is the responsibility of another framework that usesLogas the on-thread capturing of log records.We might want to revisit that in the future, but can be worked through orthogonally.
Error handling
Errors in logging pipelines are tricky and there's no single obvious way to handle them.
Right now, the visitors for
KeyValuesare infallible, because serialization failures to in-memory buffers are usually from malformed input, so there's not much you can do with an error. We might want to revisit this though.Sending records across threads
The
logmacros always borrow from their environment. Sending records across threads means serializing and boxing.This API is much simpler to deal with at the expense of allocations when materializing an owned record. In my experience, most logging pipelines are CPU-bound until the last mile where records are sent over a network or written to a file. Doing CPU-bound processing on-thread before offloading a potentially serialized record for batching IO on another thread is both simple and efficient.
It also means callers don't need to worry about whether the receiver of their records requires owned or borrowed data.
Design
log!We can log values that implement
ToValueusing the standardlogmacros:(We might want to bikeshed the syntax, the strawman implementation implements the
kvs: { ... }part of the macro, but I haven't tried to make it disambiguate with the args passed to the message yet)It's useful to be able to tweak the way values are logged. We can use an alternative in-built adapter using a standard attribute syntax:
This would be useful for types that don't meet the
Serialize + Displaybound, likePaths and mostErrors:There's nothing magic about the adapter ident within
#[log($adapter)], it just resolves to a path likelog::key_values::adapter::map::$adapter. New adapters can be added as new functions to that module without touching the macro.Custom adapters can also be written as functions in other crates and associated with key values:
The signature for
some::adapterwould be something like:Decorating the
logmacro invocations means we don't need libraries in the ecosystem with types we want to log to opt-in toToValue.One drawback of using an attribute-like syntax for decorating key-value pairs is that you might expect other standard attributes like
#[cfg]to work too. This might be easier to support using procedural macros instead ofmacro_rules.ValueA
Valueis basically aSerialize || Display. This is so that in environments where we don't have an allocator and can't useerased_serde, we can still log using the same types by default. Iferased_serdeis unavailable, values will be serialized as strings using theDisplayimplementation. Iferased_serdeis available, values will be serialized with theirSerializeimplementation.ToValueA type that can be converted into a
Value. Anything that implementsToValuecan be used as a value in the log macros.There's a blanket implementation for
Serialize + Display:There are some interesting implications of requiring
Displayin addition toSerialize. It means values need to have a single canonical human-readable representation, which is reasonable for values you want to log. Large and complex structures that implementSerializearen't usually appropriate for log records.The
Serialize + Displaybound is met by most standard primitives likei32andString, and interchange types in the ecosystem likeUuid. However, it does exclude types that you'd reasonably want to log, likePaths, and mostErrororFailimplementations. This is where adapters on thelogmacros come in handy.KeyValueA single key-value pair.
This trait has a blanket implementation for tuples:
KeyValuesA set of key-value pairs that can be visited using a
Visitor.This trait is implemented for slices:
If
stdis available, it's also implmented for collections likeBTreeMapandHashMap.See some example
KeyValuesimplementations.VisitorA type that visits individual key-value pairs.
This might involve serializing, filtering, counting etc. The name
Visitoris just so it's clearer how this API interacts withserde::Serialize.See an example
Visitorimplementation.AsMap+AsSeqThere are a few extension traits to make it easy to serialize
KeyValuesusingserde.@KodrAus
Long overdue... I've found some time to take a look.
Most of the API is "push", while this one is "pull" - control flow is reversed and I think this will create problems. Some things might require allocating because there is no way to return something holding an internal reference here etc.
I would consider:
and
this way the API is always "push" and
Valuecan always prepare anything on stack and pass a reference to it to theSerializerit got.It was a common request to make
Keysomething better than&'static str: https://github.com/slog-rs/slog/blob/master/src/key/dynamic.rs#L46TBC.
I've created pr #281 for considation for this discussion. It uses the following design:
The trait to represent a key value pair:
And for the log macro:
Currently that means that the log (and other) macros uses a
&'static stras key. But in case something else is required theRecordBuildercan be used, the newkvsmethod accepts&[& KeyValue](lifetimes elided).@Thomasdezeeuw See my previous comment. Returning
&Xis not very practical. Let's say that implementation ofKVhas to create a value by concatenating two strings. Now it hasStringon a stack, and how is it supposed to return a reference to it?@Thomasdezeeuw thanks for jumping in!
I think you've nailed the essence of what we're trying to do here, but I think the
&dyn Displaytype for values is unfortunately limiting because it can't retain the structure of the original input. This is important for drains that emit records as structured data rather than text.@dpc
In this case, the
serde::Serializeimplementation has the same scope as your proposedValuetrait, so I don't think this is actually the case here. The goal ofValueis to make it possible to keeperased-serdeas a private dependency, so that betweenstdandno_stdcontexts we're only adding APIs. It also abstracts the logic of determining whether to useDisplayorSerializeand offers us a chance to capture primitives on the stack in theno_stdcontext and avoid displaying them as strings if we can get away with it.@dpc That is a good point about the reversing of control flow though 👍 Sometimes that's a bit of a smell, so it deserves some more attention.
As for keys as
Cow<'a, str>, that seems reasonable. We could support that using a similar facade asValue, sinceCowisn't available inlibcore.@KodrAus Could you elaborate on the private dependency? I mean
serdewill have to be exported somewhere at least once.@dpc That's right,
serdewould be a public dependency but it supportsno_stdso that's not a problem. I've been trying to avoid makingerased-serdea public dependency though, because it needs to allocate, so can't work inno_std. SoValuemakeserased_serdean implementation detail so we can thread arbitrary object-safe&dyn erased_serde::Serializes, whileValueitself implements the non object-safeserde::Serialize.For logging structs I was thinking about deconstructing them before logging, e.g.
Since most structures have atleast some fields that might not need to be logged.
I also think that making
serdepart of the API (outside of the currently bits behind a feature flag) would be a mistake. I think serde is awesome and use it as well, but that might not be the case for everyone. If log should be the standard, go-to logging framework that everyone writing rust code uses, it shouldn't depend on other crates in my opinion.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
logmacros be able to take a log "object" rather than a string.Something like:
This is equivalent to writing
info!("An event has happened", name => "my_name".to_string(), count => 42);- but there are advantages of this approach: it gives you compile-time checking of log arguments, defines the logs as an API so you can document them and easily spot when they change (useful in the case where you're using a distributed logging solution and building monitoring systems on top of your logs, to ensure they don't change without good reason), and allows you to take advantage of high-performance log handling that doesn't need string parsing (if your log records get sent somewhere in binary format).@Thomasdezeeuw This does still have the problem that
user_idcan only be interpreted as text, not as a number.I have a different opinion about leaning on
serde, because any API for capturing structured data is inevitably going to look something likeserde's it makes sense to create that link so that effort invested intoserdeprovides improvements forlogand effort invested intoSerializeimplementations in the ecosystem result in more types that can be logged out-of-the-box. I don't imagineserdediverging from its current path enough to make its use inlogproblematic.What are some concrete downsides you can see from using
serde?@mthebridge Neat! I can see why some folks would find it appealing to log that way. I think we could achieve something similar in
logby using the proposedKeyValuestrait. As for thelogmacro itself, since they're imported like other items in the 2018 Rust edition I think it'd be straightforward to define your ownlogmacros in your application expecting an implementation ofLogObjectand constructing aRecordBuilderfrom it.@KodrAus I don't really need the actual type for the value,
Displayis good enough for me. However when you do need the actual type, or a way to get it, makes things more complicated and indeed my proposed API won't work.As for the depency on
serde; my main worry is stability. Currentlyloghas a fairly small API surface, with no depencies (again ignoring the bits behind feature flags). Iflogwould have a dependency onserde(or any other crate for that matter) and it's exposed in the API, it's also fixed in it. Meaning that ifserdewas updated to v2, what shouldlogdo? Change to v2, possible breaking all exiting code? And what about old code that won't/can't be updated. Or what if the ecosystem moves away from serde to another serialisation crate? Again what shouldlogdo? Stay with the now "old and unused" crate, or again publish a code breaking v2?I think that the API should remain small, yet flexible, so that
logremains the standard for the years, and decades, to come.@mthebridge I like the idea, but maybe that could be done in another crate? Like
serde-derive, e.g.log-derive. And then have a trait inside thelogcrate to support it.@Thomasdezeeuw Oh, yes - I'm not saying this should be in the core
logcrate, but that it would be good if code using this kind of approach can still use the same logging API. If the API is flexible enough, then I'm perfectly happy with adding extra crates on top. :)@KodrAus Thanks, I wasn't aware of proposals to change macro imports - I assume this is https://github.com/rust-lang/rust/issues/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
logcould be the standard for years if we don't support capturing structured data, and since logging is usually a second-class citizen we'll get the best results if we leverage existing effort.As for stability itself,
serdeis just about always a public dependency so I imagine any breaking changes toserde, if there were ever going to be any, would be made with backwards compatibility in mind because a lot of libraries and frameworks interact through its API. For the same reason I think any alternative serialization framework would need to integrate withserdein some way to gain momentum.There's no concrete answer to the hypothetical scenario where
serdev1 no longer allows users oflogto capture the data it once did until that scenario becomes concrete. I imagine that's a case we as a community would need to work through and there are probably ways we could make old and new APIs work together, depending on what actually changes. So I feel like the stability risk is already shared by the ecosystem and outweighed by the benefits of making the vast majority of data types and formats now and in the future just work withlog. I think the way I'm proposing we couple the crates together makes more sense than building a similar API ourselves. It's probably also worth noting thatserdewould still be optional, just enable some more features.But those are just my thoughts. I'm sure @dtolnay has plenty about
serde's role as a public dependency in the crates ecosystem that might be totally different. It's definitely an important discussion to have.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
Visitorrather than being pulled off them. That pushes the inversion up a layer so implementations ofKeyValuecan work with temporary state more easily. TheToValuetrait remains the same, but isn't part of the core API.I retained the
Valuestruct as a way to keeperased_serdeprivate and as a place we can do some trickery to retain the structure of primitive types likei32,bool,f32etc in no-std contexts so they don't end up being emitted asDisplay.Keyis a similar wrapper for strings that could support an owned as well as borrowed variant.Overall, the public API could look something like this:
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
log's relationship withslog. Personally, I don't think we necessarily need to unify thelogandslogecosystems by deprecating one in favour of the other. It's not uncommon for a language ecosystem to include a few logging frameworks each making different tradeoffs. It might be worth exploring the ways libraries and applications currently work through the combination oflogandslogand whether there's room for improvement.What do you all think?
@KodrAus
Great work pushing it all forward. I like this API.
About
slogandlogrelationship: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
slogwas created is because I was working with Go codebases, and libraries implementing structured/contextual logging (zap/log15), and I got sold on both ideas. It really makes sense in a bigger system, with many modules, components, workers, threads, etc.If
logwould have a "structured" part built in (as per this Issue), thenslogwould really have only the "contextual" part left on top oflog.I would be very happy if
slogcould become just a small extension on top oflog, or even got fully replaced bylog's with "contextual parts" that only "enterprise-y" users would use - since contextual logging comes with a usability price of passing "context" (slog::Loggers) around.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
slogthere is an distinction between "Borrowed" (imediate) KVs and "Owned" (long-lived, shared between many logging statements) KVs . Owned KVs are thread-safe and can be passed between threads without copying/serializing. The idea is: it costs a bit more to create them (they are long chains ofArcs), but they can be extended, manipulated and passed cheaply to other threads. Forlogto supportslog, there would have to be a way to pass thread-safe KeyValues.logmight not necessarily have end-user APIs for using them, but the facilities would be there.Other than that, I think the nice part about
slogecosystem was composability. Slog had a concept of aDraintrait, and all logging libraries implement it. Thanks to that you can take envlogger-likeRUST_LOG-controlled filtering, combine with asynchronous logger, and output some stuff to a file, some to logstash in JSON, and some to syslog, all without much sweat. I would really lovelogto have a trait likeslog::Drainto allow that (see also #267).I think you should push forward and after getting some opionions of maintainers of
log, move forward. :)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
masternow that folks working on logging frameworks or implementations ofLogshould be able to take a look at and leave some feedback.