An RFC for structured logging #296
No reviewers
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!296
Loading…
Reference in a new issue
No description provided.
Delete branch "rfc/structured-logging"
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?
Rendered
Reference implementation
Sample API docs
Hi! So we've been working through some designs in #149 on how structured logging could be supported in
log. I've since gone away and tried to capture the results of that discussion and my experiments over the year into a concrete proposal that we can refine further. It looks pretty long, but a fair chunk of that is blocks of source.I don't necessarily expect us to merge this PR even once we're happy with it, it's really just an effort to get more directed feedback on a significant API using a process we're familiar with in the Rust community.
cc @sfackler @dpc (who I know has limited capacity) @Thomasdezeeuw
Open questions:
As for serde, I want to raise an issue of serde not being capable of serializing empty arrays correctly, i e, the type information gets lost. As this issue was closed as "wontfix", this made serde impossible to use for some formats (such as mine).
Maybe that limitation is not severe enough for this case - that's up to the rest of you to decide - but I think it's something to be aware of when choosing a serialization crate.
The only thing that worries me is the inability to express data that can be sent to another thread without serialization. One idea that I have is putting additional bound on every value: https://doc.rust-lang.org/std/borrow/trait.ToOwned.html
This way values are always taken as references, but a async-logger implementation can just call
to_owned()on them and send a copy (possiblyBoxed, orArced) to another thread.@diwic while I typically love using
serde, there were multiple times where I was not happy with it trying to implement the backend (some serialization logic etc). It was typically related to handling sequences. Each time I dug, there were good reasons for how things were the certain way, and there is no way to make a serialization library that is perfect in 100% of use cases. So I can relate, but it is a de facto standard, at least right now.It seems to me, having serde dependency behind a feature flag, and thus the ability to support other solutions (or serde versions) is a good thing to have.
The pain point with libraries like logging is that they are interoperability point of the whole ecosystem, and having to introduce any breaking changes (like public dependency) can be a painful experience for everyone.
I'm not convinced that a serde dependency is the right choice for this use case. The log crate needs to focus on being lightweight in terms of code generation in particular. I think a virtual-dispatch based approach may work out better there.
For some prior art, over in Haskell-land I've been using katip. Not perfect (perhaps particularly on the serialization side?), but it's worked better than previous libraries I'd used that attempted to provide single input / multi output structured logging w/ support for ordinary text logs.
A faculty for flipping between nginx-style / apache compatible / etc. text logging would be neat too.
I haven't wrapped my head around all the details yet, but requiring serde as a depending feels kind of heavy handed to me (especially since, as far as I can tell, there is no way for the top-level crate to disable the serde integration).
I would personally feel better about this if there was another feature, only for use in the top-level crate, that would act as a "kill switch", removing the dependency on serde. (I'm not sure if that is feasible. For the log-recording part it should be, I think; for the sinks I'm not so sure).
It sounds like we're not sold on depending on
serdehere. There certainly are some big complications. The rationale was that if we don't useserde::Serializeandserde::Serializerthen we'll need to define traits that are conceptually very similar to them. We'll either have to comprimise in what can be represented by punting on the advanced APIs that makeSerializercomplex, like sequences and maps, or we'll have to introduce another API with extra cognitive load for libraries likeuuidto implement, and for formats like json to support.So maybe we can find an API that doesn't bake in
serde, and can be naturally object-safe, but also doesn't require libraries to opt-in to supporting structured logging as well as generic serialization. What I'd really like to avoid is accumulating a random bag of arbitrary traits in the ecosystem over time that need to be implemented before new libraries can be considered useful.I think that adding a dependency to include a trait is not a big issue. The problem is that in the case of
serde, this dependency is huge, which adds a non-negligible cost to everybody usinglogeven if they are not using structured logging.If instead of requiring full
serde, we would just require a thinserde-traitscrate instead, then the cost of pulling the trait might be insignificant, and just adding it by default a non issue.This might just be my opinion after being immersed in it for so long, but I can't think of any case where non-structured logging is preferable to structured logging. If it's available we should be using it.
serdeeffectively is already just a collection of traits and some default implementations, but is definitely a fairly heavy crate as far as compile times go. That cost is amortized if the library is already part of the dependency graph though.So, the easiest way is just to say that keys are
&strand values areDisplay. (Maybe there could be something that outputs theDebugstring rather than theDisplaystring.)Maybe we could just start there?
Because the moment we cross that line and say that we want something else than strings in the log backend, may it be integers, arrays, maps, booleans or something else, the question becomes much more complex because a) we then have to decide what we want to support and what we want to not support and b) all log backends need to implement support for this as well.
Surely serde can help with both, but then we're stuck with serde's design choices. Are we happy with that?
One question that isn't clearly answered from reading the RFC:
Can metadata be interpolated into the log message itself? We used a home-built structured logging framework for python and have generally captured all arguments as metadata, even if they showed up in the message. That way we don't have to write arguments twice (once as metadata, once as logging arguments) Given that all metadata must support
Displayin some form this seems trivial to support?Is it possible/desirable to have a context argument?
The examples show key-value pairs being passed explicitly, however I could imagine wanting to prepare a "map" of key-value pairs ahead of time (a context) and passing that to multiple logs.
@matthieu-m
Your logging backend could implement it and be initialized with desired metadata, that would add to key-value pairs of each
Recordwhen serializing it.If you want explicit context, that you could manipulate and pass at runtime, like in
slog, then it seems it's not part of this RFC, and the general opinion is that "contextual logging" is a bit intrusive (because you have to keep passing the context, or use some form of scopes) and it shouldn't be part oflogitself. It could however still be provided by libraries likeslog, and by having structured logging inlogthe interoperability between them would be better.I like the sentiment here, but I don't think we can really start with
Displayand build up, becauseDisplayis simply not sufficient for structured logging. All you get are strings, which is really limiting for log servers that use that structure for querying later.Sure can! While preparing this RFC I put together an an experimental repo for this kind of contextual logging.
This is something we do in .NET using message templates. I think an alternative implementation of the
log!macro, implemented using procedural macros, could do this. The syntax for thelog!macro proposed here is pretty sparten to remain compatible and to encourage crates to experiment with their ownlog!macros. Interpolating from a single bag of data is one thing to try. Another is being able to log animpl Failorimpl Erroras an argument directly inerror!.My sticking points on the serialization question are:
logand implement a trait before their types can be loggedserdesupportsWe possibly can find a way to achieve that without baking in
serdedirectly, but creating a pervasive alternative serialization framework to support just for logging, or arbitrarily limiting what can be logged both seem like non-starters to me.@sfackler this is using virtual dispatch by way of
erased-serde, but that crate has to work fairly hard to make that possible. There aren't any generics involved outside of trait implementations, which would probably exist in any implementation.The lightweight code generation requirement is an interesting one I haven't really thought about at all. Could you elaborate on it a bit more? Which usergroup is it important to?
I believe the author of serde may also have some ideas for a lighter weight serde alternative
https://github.com/dtolnay/miniserde/blob/master/README.md
Looking at the complexity concern with
serde(just ignoring the compile-time / artifact-size concerns for now), we could make life easier for formats that aren't already in the context of serialization (likeenv_logger's human-centric format) by tweaking the required trait bounds for logging. Instead of picking eitherDisplayorSerializefor structured values and facading that decision behind another implementation ofSerialize, we could always require bothDebugandSerialize, letting implementations ofLogpick the one they want through theirVisitor. So if you're already writing logs usingwrite!where structure is lost already you can keep doing that, and if you want to serialize the whole lot as a structure-retaining format like json you can do that too.Strings are indeed all we get with such a proposal, which makes writing a backend to "log" a lot easier, than if it has to support all data types that someone somewhere has decided.
If there are technical difficulties with starting with "anything Display" as values, how about starting with only
&str? That shouldn't cause any concerns with backwards compatibility if we add more types later.This seems like a proposal for a white horse with black stripes that we are told ought not be considered a zebra. I hope that I'm wrong but signs are showing that the stdlibbers are hungry to grow stdlib beyond its original mandate.
I'm not an advocate of stdlib crates competing with those of the rest of the ecoystem. stdlib Rust should foster cooperation, not competition. So, what would I need slog for if its main features were made available in a stdlib log crate? This is a question I and others will have if core functional overlaps exist.
I'm very interested in seeing a proposal for structured logging that is novel and does not overlap. Why would the authors of slog want to refactor working code just to make it line with stdlib team designs? Why should they?
@Dowwie https://github.com/KodrAus/log/blob/rfc/structured-logging/rfcs/0000-structured-logging.md#why-do-we-need-structured-logging-in-log
I totally agree with you there. Having to write a
Serializerjust to write values for a human-centric format is a formidable barrier-to-entry. The UsingVisitorto print or serialize key value pairs section has some examples of how human-centric and machine-centric formats could support structured logging. The human-centric one is actually a bit intellectually dishonest though because it omits the few hundred lines ofSerializercode for brevity. However, if we make all valuesDebug + Serializeinstead of justSerialize, then a human-centric log format usingstd::fmtcould be as simple as:For properly structured formats, where a
Serializerimplementation already exists, likeserde_json, the structured logging support can still be standardserdecode:So I think the
Debug + Serializeapproach could be a way to let implementors ofLoguse either thestd::fmtmachinery, or theserde::Serializermachinery as appropriate, without sacrificing structure altogether like we would with&str.I have also been hacking around with
serdeitself following @gnzlbg's suggestion of a thinserde-traitslibrary, and without all theimplblocks and other machinery on my box I can get a freshserdeto compile in ~2 seconds instead of ~9 (logcurrently takes ~1 second), so maybe there's an avenue to explore there too.@Dowwie
Logging is an interoperability problem. Almost every crate does some logging, and if parts of ecosystem use different logging, then in practice it will degrade to lowest common denominator.
Also, I don't know about others but I don't want to be maintaining libraries if I could get the same functionality from (semi-)stdlib.
@KodrAus
Most people just take a one that was written and doesn't care. I have used
json,yaml,cborand probably many other serialization formats in Rust, and I never had to implement ownserdeserializer.Even less so with logging, where people typically just want to dump a bunch of json logs to ElasticSearch. For
slograrely (never?) do I hear about people wanting human-centric input other than whatslog-termimplements. I mean ... "human-centric output" is just a bunch of lines. Anyone can have preferences, but it's just not worth implementing again for every project.@KodrAus
slog already does something like this, I think without proc macros; named format arguments are interpreted as structured metadata in addition to being formatted, while anonymous ones aren't. It's nice to use.
Well,
slog-termdoes implement its ownSerializerfor its format, it's just not aserdeone. I ended up going down a similar path inenv_loggertoo while playing with the API this RFC proposes and writing aSerializer. Since there are a number of terminal loggers based onlogalready it does seem worth exploring how they could be better supported. I don't think the requiredSerialize + Debugbounds rather thanSerializewould be a problem when converting fromlogintoslog, but it might be a problem when converting fromslogintolog. If that's the case then it's not really suitable.This is true, there's a lot more value to get out of structured logging when you use a log store that supports working with structured data, like Elasticsearch. That's why I don't think we should punt on the actual structured serialization support for this RFC.
Ah gotcha. We could do the same thing in
log!, but couldn't retain the structure of those format arguments without breaking existing users because the trait bounds would be different. It could be done without the same breakage using a proc macro though that's able to interpret the format string and know which values need to be interpolated from the one set of structured key-value pairs:I've spent some time going around in circles on
serde, so maybe we could look at some alternatives and their respective trade-offs properly? Like turning theVisitorinto something likeSerializer, likeslogdoes.The trade-off there that I see is that we'd then need another trait like
Serializethat's implemented throughout the ecosystem for loggable types, probably also alongsideserdeanyways.Ok, I spent some time exploring the serialization API more to remove the required
serdedependency from this RFC and came up with a proof-of-concept.This API doesn't require
serdeby default, but can support it using a Cargo feature. Without theserdefeature enabled it's super lightweight, the idea being that out-of-the-box we just support a limited set of primitive types as structured key-value pairs, but that set can be expanded to any type that implementsserde::Serializewhen the feature is opted into. TheSerializetype from this crate doesn't become a public dependency because you can't implement it manually (that also lets us change its default bounds using Cargo features without fear of breakage), and a reasonable set of types is still supported even without theserdefeature.I think this approach can mitigate some of the concerns about
serdebeing too heavyweight, but not miss the opportunity to take advantage of its already extensive ecosystem. Any thoughts?Ok, what do we think of this API, based on the serialization proof-of-concept I posted before? I've stuck with the visit terminology over the serialize terminology because actually serializing a key-value pair is just one thing you might want to do with them. Other things include checking whether a specific pair is present and doing something with its primitive type, like comparing the timestamp on a record to one that was previously set in some ambient context to calculate the elapsed time.
I changed
KeyValueSourcetoSource,VisitortoSourceVisitor, andSerializetoVisit. TheErrortype is basically the same as what's currently in the RFC.the
log!macros would be able to accept idents as keys, and any expression that implementsVisitas values.Why
VisitorandSourceVisitor?The API could be smaller if there was just one
Visitortype:This might seem like a simplification, but what it's really doing is just making the sequence of operations in serializing a key-value pair implicit. In our format that implements
Visitorwe'd need to think about values being serialized before keys, keys or values being serialized multiple times, or being given a primitive likevisit_strinstead of a key or value and having to guess which one it is.So having one trait,
SourceVisitor, that surfaces key-value pairs, and another trait,Visitor, that looks at individual values lets the format decide exactly how it's going to work with its pairs. It also means we can lean onSourceVisitorto work with pairs consistently so that ergonomic methods liketry_for_eachandserialize_as_mapcan be provided onSource. With the combination of these two methods I actually haven't found myself even needing to write aSourceVisitormanually in my experiments with this API.Why
structs forKeyandValueinstead of trait objects?Using structures for
KeyandValueis for backwards compatibility. With adyn Traitorimpl Traitwe've got all our cards on the table, and it's much harder to introduce changes without breakage. Using structures we don't have that problem. We could also abstract over owned and borrowed keys and values, and provide some useful methods using static rather than dynamic dispatch.@KodrAus apologies for my ignorance, does
logalready support or will this structured logging change add support for multi-output from a single structured log record?@bitemyapp This is unrelated to this feature. Technically it is possible with
logalready, butlogwould have to embrace "composable loggers", provide a common trait for interoperability to make this effortless and common (LikeslogsDrain) Please open another issue (if one does not already exist). As far as I can tell this RFC is compatible with functionality like this already.I guess there will be some bikeshedding over exactly what types are to be expected here? E g, I don't see myself wanting to log a
charvery often (and if I do, I could log it as astr).Another thought is what to do with
Option. We could make that skip the key-value pair if the option isNoneand log the unwrapped contents if the option isSome, maybe?For comparison: https://docs.rs/slog/2.4.1/slog/trait.Serializer.html
@bitemyapp Yeh, this is another feature that's a logical next step from structured logging, but I haven't tried to tackle it as part of this RFC besides trying not to design ourselves into a corner. Personally, I'm not sure that we need to support too much composition in
logbeyond what's needed onRecord, because frameworks likeslogalready do this really well, and as a facadelogdoesn't necessarily need to care too much.@diwic Sure, let's colour some bikesheds!
u128andi128, I forgot about those.visit_charcould default tovisit_str, using a method likechar::encode_utf8.SomeandNonein some way.Somecould also default to justvisiton its inner value.Instant.What else do we think?
Other APIs for comparison
slogHere we have default implementations for most of these methods that forward to
emit_arguments. Based on these APIs, I can't see any issues with us adapting betweenlog::Sourceandslog::KV.serdeHere we have a whole lot of extra complexity for just about any datastructure you can represent in Rust.
One major drawback of the design I posted is that while it doesn't technically make
serdea required dependency, it does make it implicitly required for any implementation ofLog, because there's a chance that some of theValues on a log record can't be captured by theVisitortrait (some library might opt in toserdeand log aVecor something). That's why there's thatVisitor::unsupportedmethod, but it's a cop-out and the experience of having to deal with it would be poor.So I've been thinking about how
slog::Serializerby default forwards its methods toemit_arguments. We could do something similar inlog, so instead of getting handed some unrepresentable value in yourVisitor, you can always at least write it usingstd::fmt. That would mean that instead of doing a blanket implementation ofVisitfor anyserde::Serialize, we'd do a blanket implementation ofVisitfor anyserde::Serialize + std::fmt::Debug.So updating the API from before:
That way a library implementing
Logcould always get a reasonable representation of any loggable value without depending onserde.Alrighty, I've gone ahead and updated the RFC based on the feedback so far. It removes
serdeas a required dependency, so we can support structured logging without opting in toserdesupport. Instead, it makesserdean optional extensibility point in the ecosystem so thatlogdoesn't become a massive public dependency of its own to support structured logging in a way that's nice for users to consume. So with default features,logsupports structured logging but doesn't bring in any new dependencies.I've also added a section on how we could manage getting an owned version of the key-value pairs that is
Send + Sync + 'staticefficiently.If you'd rather poke around an example implementation, I've got one here
Thank you @KodrAus for writing this RFC.
I however don't think this is the right way forward for this crate. Aiming to be the standard logging crate means supporting a lot of use cases, while not growing too big. And I my opinion these additions make the crate too complex and too large, even when leaving out serde.
The number of types and trait required to support this doesn't seem to be worth it, to me atleast. Eventhough I use serde myself I also think that serde is too complex, it only gets away with it because it has a limited number of backends (e.g. serde_json) and has nice macro support to derive the required frontend traits.
However serde only implements one way to serialise data structures. Maybe a different way of generic serialisation, one that is easier to implement, should be the way forward.
Missing
=.[...] require to crates implement [...]
This paragraph conflicts with itself, it says
serdeis optional follow by "crates should implementstd::fmt::Debugandserde::Serialize".[...] are traits they should b
ye considering already.Maybe mention that anything before
;works just like theformatmacro (& friends) work.Again this indicates to me that
serdeisn't optional.Maybe support types that
Deref/AsRef/Borrowinto one of these types as well? For example I have a couple of that are defined asstruct MyId(usize), would be nice if those were supported out of the box if it implemets one of those traits.But this can wait until later perhaps.
How does this look on the loggers side? Is
userflattened? Or does this create a key "user" -> valueuserstructure mapping?You're using a trait here that not has been yet in this RFC. Maybe put the definition of it before using it, or at least refer to the trait definition. Reading this top-to-bottom made it somewhat surprising to find this here.
Same comment as with using the
Sourcetrait.All the code examples seem somewhat repetitive, any possibility of providing a derive macro? Like serde does.
Do we really need a custom error? Is there any serialisation format that can fail? Can't this be relaced by
io::Error?This entire code section is repeated (from what I can tell) below in different sections effectively making this bit obsolete and only making the RFC longer.
Just a general comment about the ordering of the structure/trait here: define types before using them. The first method
RecordBuilderkey_valuesusesErasedSource, but I have no idea what that is. So I find to scroll down to find and scroll back up again, this makes reading this RFC top to bottom somewhat unpleasant.@Thomasdezeeuw thanks for taking the time to read through this giant document! I appreciate your input on how readable it is(n't). Before working through those though maybe we should try address the main criticism you've raised.
When talking about this API being too big are you talking about the surface area or the volume? I mean, do you think the public API is too big, or do you think there's too much going on behind the scenes to support it?
Personally, I don't think the public API is too big here, but there's definitely a lot more going on than in the simplest API we could imagine for key-value pairs.
If we look at the simplest possible representation we can see where the API proposed here abstracts over it:
There are two abstractions that we work with:
SourceVisitThe
Sourcetrait abstracts storage for key-value pairs:This abstraction is important for being able to convert records from other frameworks to and from records in
log. If we only supported&[(&str, &Visit)]then we wouldn't be able to efficiently work with types from other frameworks, likeBTreeMap<String, Value>, orArc<CustomMap>.The
Visittrait abstracts serialization for structured values:This abstraction is important (over just something like
std::fmt::Debug) because we need to be able to inspect the structure of values in order to serialize them or maybe style them in a particular way in a terminal. We could just carry primitive values in anenumlikeserde_json::Value, but then we have the same problem we did with the concrete slice inSource. We make it more difficult for other logging frameworks to integrate withlogwhen their values have a different underlying structure. Alternatively we could just carry a raw trait object and expect that to be downcast to a known concrete type. That wouldn't work either becauselogneeds to support arbitrary log producers communicating with arbitrary log consumers. Unless you control both the producer and the consumer you couldn't reasonably know what to downcast that trait object to. So we need some serialization API that forces implementors to conform to some contract that lets anybody reasonably determine its structure.The API proposed for
Visithere is already a very simple serialization API. It's just one that can optionally carryserde::Serializewith it. That lets it punt a lot of complexity that would otherwise be introduced for arrays, maps,#[derive], formats, and managing breakage. We get all that for free(ish). There's internal (not public), module-local complexity to get these benefits, but I think localized complexity is much more manageable and is a fair tradeoff to make inlogto offer the ecosystem the most appropriate API that it can for producing and consuming structured logs.So I appreciate the need to keep
logtight and fundamental. I think based on the usecases they need to support, bothSourceandVisitdo achieve a good balance. I've also got the assumption that structured logging is a really fundamental feature, so its API deserves an appropriate amount of complexity for the benefit that it brings the Rust ecosystem.@sfackler do you have any more thoughts?
Json can fail if you give it non-string keys, and any printing done through the
Writetrait can also fail. We do need our own error type because thelogcrate needs to work in no-std environments, andio::Erroris only available in the standard library.Ah these examples are all just variations of the same thing; implementing the
Sourcetrait where the underlying data is in various different shapes. I'm not sure a macro would be worthwhile for derivingSource, because the way you'd surface key-value pairs is really dependent on what the underlying source is.If the
kv_serdefeature is enabled thenuserwill be serialized as a map, not flattened. If thekv_serdefeature is not enabled thenuserwill be serialized as a string using itsDebugimplementation.Unfortunately something like
impl<T: AsRef<U>, U: Visit>wouldn't be coherent,impl<T: Deref<Target = U>, U: Visit>would only cover smart pointers, and as a blanket implementation it would conflict with the optional one forT: Serialize + Debug. This would be a case where if you want to logMyId(usize), you can enable thekv_serdefeature and deriveSerializeonMyIdto log it as a newtype.Yeh the definition of optional here might be a little unclear :) By optional I mean anyone can depend on
logand use thelog!macros to log structured data, or implementLogand work with the structured data on a record withoutserdeentering the equation at all if you don't opt in to thekv_serdeCargo feature. Thekv_serdefeature addsserdesupport, but is totally optional. Any crate callinglog!macros can work without this feature. Any crate implementingLogand working with the key-value pairs can work without this feature. Any logs produced whenserdesupport is opted into can be visited by anyLogimplementation, even if they haven't opted into the feature.The limitation of structured logging in
logwithout thekv_serdefeature is that only a set of common types from the standard library can be logged as structured key-value pairs. Most types in the ecosystem likeUuid,Url, andDateTime<Utc>implementserde::Serialize, so this RFC proposes leveraging that existing investment in serialization boilerplate for libraries that exist today, as well as libraries that are getting built in the future, instead of inventing a new framework that they will need to support in addition toserde.@KodrAus Saying that the crate would become too big wasn't clear, your right. What I meant was that the public API would become too big, i.e. it would have too many types (struct/traits). If I counted correctly 7 new types would be added to the public API. On top of that another couple helpers, e.g.
SerializeAsMap, and more types when the serde feature is enabled, e.g.ErasedSource. The currently crate exposes 7 types (+ 2 builder types), which means the public API would be at least become twice as large.For a "simple" logging facade it doesn't seem so simple to me.
But I do agree that structured logging is a fundamental feature. So perhaps with some structuring of the public API, e.g. by pushing most
Logimplemening types to the back, while pulling the logging macros to the front. This way "users" of the log crate keep a simple public API, while the "Logimplementers" have to deal a more complex API.P.S. I hope I wasn't too harsh with my feedback.
@KodrAus To continue the discussion around the
SourceandVisitortraits; could this be solved with an aserde_json::Valuelike type in an iterator, so&dyn Iterator<Item = (&str, Value)>. This means thatBTreeMap<String, Value>, and similiar types, can be chained onto it. AndValuewill keep a type around. Of courseValuecan't possibly support all types, so maybe a variant should beOther(&dyn Display), or perhaps a similiar trait. Or with a serde feature:Serde(&dyn serde::Serialize).Upside is that the public API remains small, adds only a single type. Downside is that the order of the iterator is now unspecified, I'm unsure if this is important for you. And we still have fully typed value (only when they fit in
Value) when logging.Your comment makes a lot of sense, maybe its worth it to repeat that in the RFC.
Ok.
Ok.
Hmm, I wouldn't necessarily describe
logas a simple logging facade. At least I wouldn't make simple its primary goal. Instead, I'd callloga fundamental logging facade. Simple is a nice goal, but fundamental is what would letlogsupport the development of Rust's logging ecosystem rather than just being an obsolete artifact of it. Other people might have different opinions than me on that though.This is actually where I started earlier this year, but ran into some complications. The problem with an iterator approach is that it's not object safe, and making it object-safe requires some unappealing public machinery for progressing and resetting the iterator. So the
Sourceandsource::Visitorsystem is conceptually likeIntoIteratorandIterator, but retains object safety by pushing the iteration inside theSource. You just get a chance to observe that iteration using aVisitor. This pattern lets us build a complimentary set of adapter methods like we already have withIterator. Those adapters make it possible to normally work with aSourcewithout having to define anyVisitors at all. So theSourceandsource::Visitorapproach results in the same number of traits to work with as we'd have withIntoIteratorandIterator.The
Valuetype you're describing isn't too far off the original version ofValuefrom this RFC. I ended up changing it toValue,value::Visitandvalue::Visitorin the process of limitingserde's role in the API. It turns out it's roughly the same number of types. Even if you just have a concreteValuetype you still need a trait likeToValuethat can take an arbitraryTand turn it into aValuefor thelog!macros, and for records from other frameworks. Exposing the variants of thatValuedirectly as anenumwouldn't be desirable because of backwards compatibility concerns. You'd either need a non-exhaustive catch-all arm when matching over the variants, or you wouldn't be able to add variants without breaking consumers. Neither of those options is appealing. So you'd end up needing a trait likevalue::Visitoranyways so callers could guarantee that all values can always be logged regardless of internal changes to the representation of theValue. So theValue,value::Visitandvalue::Visitorapproach results in the same number of traits to work with as a concrete type does. I do feel like thevaluemachinery deserves a lot of scrutiny though.So I don't think just aiming to reduce the number of types is necessarily going to result in a more understandable public API. That lands us in a state where we make arbitrary limitations for the sake of an API we assume is more understandable. We want the API to be understandable through its use. I think the way to do that is to look at the interactions of these types for unnecessary complications, rather than just treating their existence as a complication. It is definitely worth making each type justify its existence though.
To make it a little easier to explore, I've pushed up the API docs for this proposed API.
Working through the process of pushing
serdefurther out of the proposed structured logging API, I've been playing with another alternative serialization API, that's similar to the direction a prototype tracing API fortokiois taking.Something like this would remove all the wackiness around changing trait bounds based on Cargo features in order to avoid loggable types depending on
log, but would create a pervasive public dependency, and put us in the business of maintaining a serialization framework. I've previously been trying not to do this. We might be able to mitigate those concerns though if we were aiming to build a common value serialization abstraction that all logging frameworks could depend on instead of defining their own.This surprised me. I'm use to (not in rust) doing messages like
"action {action_name} completed in {duration}ms", and still getting the properties as real columns that I can filter and pivot on.Yes, that's a better way to do things, but we couldn't do this and maintain potential structure without potential breakage to callers of
log!, because the trait bounds within that format would change.Ok, I've got something more to share on the serialization front. This library (with rough source here) is similar to the last one I posted, but has a smaller surface area. It's no-std, object-safe and integrates optionally with
serde. It seems like something we could build structured logging serialization off.For integrating an external serialization framework like this into
log, we could either:serde. This doesn't offer any benefit over what the RFC currently proposes.logwould have more than zero dependencies by default. This was a problem forserdebecause it takes a while to compile and object-safety requires boxing.logso it doesn't directly consume an external serialization framework. That means implementors of this value type would need to depend onlog.log!macros have to work a bit harder to serialize their structured values.Personally, I'm thinking the third option could be worth pursuing, since callers would already not be able to log their
serdedatastructures by default.Does anybody else have any thoughts?
I've managed to convince myself that it's not super important for structured logging in
logto be able to capture all the types in the ecosystem that can be serialized by default. It's less user-friendly, but it leaves the door open for someone to build a better set oflog!macros that can capture structured values differently, and could find their way back tologitself one day.So if we don't need to bake a framework in out-of-the-box because we don't need to capture its values out-of-the-box, then we can probably move forward with a much slimmer values API, and see what direction
tokio-traceandsvalgo in.I was thinking a public API something like:
Internally, we can use private methods on
Valueto retain the structure of integers and other primitives when forwarding to aVisitor.As a provider of dataustructures, like
uuid, you can implement theToValuetrait yourself, but the only way to get a hold of aValueis to callToValueon another type that already implements it, or useValue::from_debug.As a consumer of structured logs like
env_logger, if you don't care about structure, you can just implementVisitor::visit_any. If you do care, you can override provided methods likeVisitor::visit_u64.Later, to extend this system to support another serialization framework, like
sval, we would:Value::from_svalmethod or something.sval::ValueforValueas well asfmt::Debug.For
serdeit would look basically the same, but could be supported in terms ofsval.That way, any implementation for
Visitorcould treat aValuelike asval::Valueor afmt::Debugwithout anything else having to change.That could be a way for us to unblock on the serialization question.
@KodrAus For what it's worth, I'm a big fan of your revised proposal.
Thanks @davidbarsky!
I have gone and spiked out an implementation based on that last comment, so will update the RFC text accordingly (if anyone's interested in the meantime, the rough working implementation is here).
Something else we might want to look at is the way
tokio-tracehandles values. It's a bit different toslog'sKVtrait and this RFC'sSourcetrait; instead of having an up-front collection of key-value pairs that you serialize on-demand, you have an up-front collection of fields, that only contains the key. Values are individually streamed later. The nice thing about this approach is thattokio-tracedoesn't have to erase any types when passing values, or introduce any significant generic machinery. I'm not sure if we could do it the same way inlogwithout going against the grain of its current API, but I think it's worth looking at.How does this work? Can you link some relevant code or something? :)
Sure, there's a PR in
tokiothat introduces it: https://github.com/tokio-rs/tokio/pull/827The relevant API would be
Subscriber, which is loosely like aDrain. It accepts its field values independently of other metadata, which is how theevent!macro streams its values through one at a time.@KodrAus Thanks. I'm having a hard time wrapping my head around it. Looks like combination of
slog-scopewith a lot of weird machinery. 😄I might be totally off here, but it all seems terribly complex, and heavy (performance-wise). When looking at implementation https://github.com/tokio-rs/tokio/pull/827/files#diff-96a079b381f1a34afe99d4e592ca9de7R71 I see Mutexes and collections and a lot of
to_owned,cloneetc. Even todos about "GC"https://github.com/tokio-rs/tokio/pull/827/files#diff-96a079b381f1a34afe99d4e592ca9de7R292 .
In
slogthere's hardly ever any allocation necessary. To the point where stuff likeis_enabed(&self) -> boolare unnecessary, because it's cheaper to just give theDrain/Subscriberthe data and let it do nothing with it if it's not interested, rather than bother branch predictor with another branch. I might be wrong but I think it's going to order or even two slower thanslog, especially considering thatslogcan actually very efficiently offloadRecords to other threads.I don't know... might be there are good reasons for it, given that it wants to record "information about temporality and causality", but still it seems heavy.
Also, I don't understand the point about metdata. It seems like everything is based on
record_debugand couple of other types, so the type-information seems lost. https://github.com/tokio-rs/tokio/pull/827/files#diff-96a079b381f1a34afe99d4e592ca9de7R213@dpc I'm actually a bit unfamiliar with the codebase myself, so if you direct your feedback to that PR you'll probably get some clearer answers 🙂 I think more eyes on it are appreciated.
The code snippets you posted are just part of a rough-and-ready example though I think.
@dpc The mutexes you're pointing out are in a file called
tokio-trace/examples/sloggish/sloggish_subscriber.rs. While I concede some of the examples could be polished up—that's partially my fault—I don't think it's representative of Tokio Trace as a whole.But can mutexes and allocations actually be removed there? I don't fully understand everything, but it seems to me that not really.
On the matter of mutexes, the following fields located in
SloggishSubscriber......can be replaced by lock-free, concurrent data structures. For instance, one candidate to replace these data structures would be Crossbeam's Skiplist, which provides access to concurrent lists and maps.
On the subject of allocations in subscribers, I'll defer to subject matter experts. However, Tokio Trace is designed to incur zero runtime costs if no subscriber is collecting spans or events.
I'd also like to add that this thread is not the correct location to discuss Tokio Trace's performance characteristics. Any dicussion of Tokio Trace should pertain to how Tokio Trace might interact with this RFC.
If the discussion is about viability of
tokio-traces model as an alternative for parts of this RFC, then I think it's totally fine to discuss its performance, or any other aspects of it. Though I agree that it might dominate the discussion, which would be unfortunate.Well, at least a check if tracepoint is enabled had to be made, so there is some tiny performance cost, no? And https://github.com/tokio-rs/tokio/pull/827/files#diff-6d30418ad739864a993dd6472915f9aeR74 doesn't look as NOP to me, but again I understand that it might be just an example or something. :)
Also, the performance with debuggin/tracing enabled is very important. First of all, logging is not only used for debugging, and it's legitimate needs to have some form of tracing/debugging enabled even in normal, production operation.. Second of all, if enabling debugging brings the app to it's knees, then it's not very useful for many apps. Real world example.
Anyway. I'm not trying to be mean. Just pointing out that perf. is important, and trying to understand the implications of an alternative model, that I wasn't familiar with. I honestly don't know how much if any overhead this model has.
Yeh my intention when bringing up
tokio-tracebefore was just to look specifically at how it splits key-value pairs into a concreteFieldSetthat describes the fields, and independently streamed values. Inlog, that might look something like:Instead of the current:
The reason I think the split approach goes against the grain of
log's current API is that inlogwe don't really have a way to know what context we're in when callingrecord, so untangling interleaving calls torecord_*would be tricky for existinglogimplementations.I'm not sure how much we can really explore the implementation of
tokio-traceitself in the context oflog, because they're fundamentally different paradigms. Design Decisions that make sense for one won't necessarily make sense for the other. At least that's the take-away I'm getting.Alrighty! The RFC text has been updated based on the latest discussion. I've updated the reference implementation and docs in the original PR comment.
I've also included a minimal initial public API we could land that would get us started and let us build up the serialization story in one of a few directions without breakage.
Any thoughts on this latest approach?
@KodrAus This looks good to me.
Erm, I'll throw in some bikeshedding on the macro syntax—I think commas might be a better delimiter than semi-colons, to gain symmetry with
write!et. al.Yeh, the proposed macro syntax is:
So there's a single semicolon that separates structured from unstructured fields, that are separated by commas. This is for backwards-compatibility, so that the macro can split the unstructured fields we already support today with trait bounds determined by the format string from the new structured ones that have different trait bounds. If we put them all together then we'd end up breaking existing uses.
Once we've landed some kind of structured logging though I'm keen to start experimenting with a new procedural macro based
log!implementation externally that could peek into the format string and just interpolate from a single list of structured fields.Understood! I didn't realize that putting all of them together would be a breaking change. My bad for missing that.
A possible future extension we could make to
Valuewould be letting you treat an error type explicitly:with whatever bounds it is we have to satisfy to make the returned error from
as_errordowncastable.So we touched on this a bit at the all hands, and while I don't think any major red flags were raised, it is a vast piece of API to consider. At least we can land it incrementally.
One thing we didn't get a chance to look at is the macro syntax. Unlike the traits and structures we probably can't land a subset of the macro. Right now, the RFC macro syntax is:
It's a shame to have to repeat format args in the structured list if you don't just want them interpolated into the message, but I couldn't think of a backwards-compatible way to do it. But, maybe we could use a token in the macro to opt-in to treating format args as also structured:
So the leading
stells us format arguments should implementToValueand be in the set of key-value pairs in addition to being interpolated into the format string, avoiding having to use two sets (which has been raised here a few times as not ideal), or having to break existinglog!callers.Does anybody have any other thoughts on their preferred macro syntax?
cc @sfackler
Using some kind of switch within the macro is a strategy that would also work for treating the output of #317 as an optionally structured value too.
Macro syntax: See alternative considered for #317, using '=' as marker token. At least in that case it seemed to me, like more to teach with DSL, than is the case with dedicated function-like macros. That said, the -v macros are more unique in that they are restricted to a single value.
Have or might you consider that as an alternative? Like a parallel set of -s or other suffix macros where all named parameters are consider structured and available for the message format as well?
Also, for many cases where this would actually be used, would it be adequate and/or potentially more convenient to just configure something with the logging implementation to format specific structured values in the output, either before or after the passed message?
(I've held off on commenting here, trying to catch up on its evolution and also understand the tokio stuff, but...)
Have or might you also consider adding the
rust-log-mdccrate (and what I presume is its java log4j/slf4j inspiration) as prior art? I think that is relevant because for use cases like including a user ID as structured attribute, it may be nice to "register" that value as a thread local or separately passed around "context" associate-array-like type. An exclusively thread-local approach doesn't work cleanly withasync(which wasn't a Java thing, back in the day), at least without library support, but isn't tokio-trace'sSpanconcept similar?The marker I was thinking of was something like
kv, but=is a reasonable alternative too!I think we could end up with a macro-explosion going the separate suite of macros route here, so something that doesn't require new macros for interpreting structured data differently would be better I think.
That's an interesting idea, and you could support it in a logging framework built on top of
log's structured logging, but it would require the data we're interpolating directly into the message is also available as key-value pairs to process independently, which we need a marker token for in the existing macros.Thanks! I haven't looked at this crate before so will check it out.
I for one would much rather have separate macros that have good syntax than a single unified macro with awkward syntax. Couldn't they even have the same names, just residing in a different module and requiring manual import?
@Ralith do you find the
info!(kv; "format", arg; arg)style awkward? If so, what is it you don't like?There's a whole new world of improvements we could make to the
log!macros if we built them as proc macros instead of using macro_rules v1 like they are today. That's something I want to explore in a separate crate before trying to circle back intolog. Without proc macros I think the structured logging support we can ship is bound to feel grafted on in some respects.I think the problem with shipping separate macros that require manual imports is a lack of discoverability, and still working with consumers that want to
#[macro_use] extern crate log;to bring everything into scope. On the other hand, we could punt entirely on macro syntax for this RFC, and just not surface structured logging in the current macros for now. Then we could experiment with new macros externally.@KodrAus I tend to agree with @Ralith and I do think
info!(kv; "format", arg; arg)is awkward.If that is what results in the final design there are decent odds I'd end up making a wrapper crate with different syntax and I'd rather not proliferate a logging API idiolect if I can help it.
Thank you very much for your efforts towards structured logging! It's a faculty near and dear to me and you've made tremendous progress in a short period of time.
Ok, I think it's probably better not to ship macro support that users don't like, since we can work on it externally, and frameworks like
tokio-traceandslogthat are already structured can integrate withlogwithoutlog's macros surfacing its structured logging support.Alrighty, I've updated the RFC text to punt on the macro syntax.
I'd really like to be able to spend some time exploring different macro designs that are structured off-the-bat. There's still tangible benefits to shipping a structured logging API in
logeven without macro support out-of-the-box by enabling better integration with existing structured frameworks, and opening up the design space for the community to bootstrap newlog!macros that suit their needs. So I'm not suggesting we never add structured support to thelog!macros inlog, I'm suggesting we just ship what we need now to unblock experimenting with new macros externally.What do you all think?
I meant to contrast it to taking structure from named format arguments directly, as in the
info!("the format string with a {number}"; number = 2);example. Being forced to duplicate arguments for them to appear in both the message and the structured data would be unfortunate.That seems like a reasonable idea.
Alrighty, this has been running for a quite a while now, and thanks to everyone that's been involved so far it seems like we've worked through the major parts of the design space.
cc @rust-lang-nursery/libs and the community: shall we kick off a final comment period for this one? If you'd like to register a concern with the RFC please leave a comment here! If we haven't received any by Friday, 8th of March then I'll merge this one and work towards PRing the initial minimal API proposed in the text.
I appreciate that this is an enormous document, and the implications of various design decisions are pretty well buried at this point. So any PRs that introduce structured logging support will be small and incremental, so we have an opportunity to discuss them just-in-time too. I personally consider this RFC more of a guide than a commitment.
I wanted to add in a little plug for something that the
serilogpackage in .NET does that has been really useful when sifting through log messages, and that is to allow logging of the message template without substitution. As a structured log, it becomes immensely easy to do a search for the template, particularly if values haven't already been substituted in. Is there a way that we could do this and also give a logging backend access to the original message template? (Not sure if this would be something in this RFC, or maybe a different one, but structured logs and templates work really well together.)@neoeinstein Sure! That would be a feature of the
log!macro to capture the format as a template and/or as a fully interpolated message. Serilog's templates conform to a standard that an alternative log macro implementation built on top oflogcould also use instead of Rust's standard formatting syntax if it wanted to. That template could then be added as an ordinary key-value pair with a special name (like@mt).EDIT: Just to add, one of the motivations for the
Source::getmethod is for poking at well-defined key-value pairs like templates and timestamps.Merged!
Thanks everybody that's given their time and input so far ❤️ Now we'll start building up the implementation incrementally in
logitself.We'll tag these PRs with a GitHub label so you can find them, but
logis fairly low traffic so watching this repository shouldn't generate too much noise.@KodrAus I realise I'm very late to the party, but would the API proposed by this RFC supported logging nested values? The use case I'm thinking of is when I have a
HashMaprepresenting an HTTP request's headers, and want to log those under a "headers" key. I couldn't see any mention of nested values in the RFC, and also couldn't infer whether or not they'd be possible to support.Hi @atroche 👋
Ah yes that scenario is actually supported through external serialization APIs. So, for example, the current unstable implementation supports a framework called
sval. So you can capture aHashMaplike:We haven't spent much time on how we might surface that through the macros just yet though.