Tracking issue for kv_unstable (structured logging)

[KodrAus]

Tracking issue for the implementation of #296. See also #149

• Initial implementation (Build out initial key values API #324)
• Integration with frameworks and loggers:
  • slog
    • Zero-allocation conversion between slog::Value and log::kv::Value. We should be able to do zero-allocation conversion from log to slog, but may need to allocate from slog to log.
  • tracing (log: Support structured values tokio-rs/tracing#341)
    • Zero-allocation conversion between tracing::Value and log::kv::Value in the event! macro (Make it easier to create a Value from owned or erased external types #339)
    • Capture std::error::Errors as Values
  • fern
  • async-log
  • std-logger (Print key values Thomasdezeeuw/std-logger#14)
    • Some way to tell whether a Source has any key-value pairs (Add a count method to Source #329)
  • femme
  • env_logger (Add support for Key-Value data in log records. rust-cli/env_logger#137)
  • antlog (an experimental wrapper to prove out requirements)
    • A way to get specific values (Add a Source::get method for finding a single value #335)
    • A way to coerce a value to a common type (Support coercing structured Values into primitive types #379)
  • Please suggest others to track!
• Explore macro support (key_value capable log macros #343)
  • log!("msg {}", interpolated, { key: value }) (kv macro support #353) - We ended up having to revert this in log, but are experimenting externally
  • log_kv_macro
  • log_macros
• Integration with serialization frameworks:
  • serde
    • Conversion between serde::Serialize and std::fmt::Debug (Add key and value methods to DebugMap rfcs#2696). See serde_fmt.
  • sval (Add structured support to kv::Value using sval #342)
• Micro benchmarks
• Documentation and examples
• Stabilization review
• Open questions
  • Should Source::count return a Result<usize> instead of a plain usize?

[yoshuawuyts]

@KodrAus thanks for all the work you've put into this (and linking to this issue from a forum post).

I was curious: is there a release planned that includes the beta version of kv? I actually wanted to use the beta for async-log, but given there wasn't any release yet it wasn't possible 😅

[KodrAus]

Hi @yoshuawuyts! 👋

Right now any release of log we publish will include this API under the kv_unstable feature gate, but we're not ready to commit to backwards compatibility just yet. So if you depend on log from git then you can access the API:

[dependencies.log]
git = "https://github.com/rust-lang-nursery/log.git"
features = ["kv_unstable"]

I think what we need are a few draft PRs in some of these log frameworks that tease out any breaking changes we should make, and then will be able to publish a release that replaces the kv_unstable feature gate with a kv one.

[yoshuawuyts]

Right now any release of log we publish will include this API under the kv_unstable feature gate,

Oh oops, maybe I was being a bit vague. The last release on crates.io was done in October 2018, which means currently no releases ship with kv_unstable on crates.io. Which in turn (I believe) means we can't ship any versions to crates.io.

In order to help test this feature, it would be nice if there was a release on crates.io with the ["kv_unstable"] feature available. For experimental technology such as async-log I think we can get away with publishing a version that directly depends on this feature, and keep updating it as it's polished.

So my question is: could a version be of log be published to crates.io that includes the experimental flag?

P.S. Thanks for taking time out of your day to reply to my questions!

[KodrAus]

In order to help test this feature, it would be nice if there was a release on crates.io with the ["kv_unstable"] feature available. For experimental technology such as async-log I think we can get away with publishing a version that directly depends on this feature, and keep updating it as it's polished.

Ah this sounds fair enough. I think we can get pretty far without needing to break anything, but it's probably going to happen at some point. But right now it is harder for folks to get started with these new APIs, so once #339 lands I'll put together a release so you can depend on it from crates.io and browse the docs on docs.rs.

[yoshuawuyts]

@KodrAus in the top-level post there's an entry about "Explore macro support". Do you have any plans to experiment with this?

We've integrated key-value logging in lrlna/femme#1; all that's missing now is a way to create key-value pairs and send them to a logger. Even a small code example would be helpful, but ideally there'd be a small log crate that could work with this.

Also: is it perhaps useful to open a separate issue to track/discuss logging macros?

---

edit 2019-07-21:
Ah, I think I figured out how to log a kv-pair!

let record = log::Record::builder().key_values(kv_pairs).build();
log::logger().log(&record);

[KodrAus]

Ah yes that Record::key_values method is the way you can attach key-value pairs to a record in the absence of macro support. It needs to be a &dyn Source.

Opening a separate issue to design macro support sounds like a good idea! We’ve got a couple of constraints but also plenty of opportunity to improve things.

[yoshuawuyts]

Macro issue created: #343

[yoshuawuyts]

Created a crate for shared types in key-value logs (to mark pairs of logs) -- https://github.com/yoshuawuyts/log-types. Not sure yet how useful this is, but I think it might be a fun reference of how to create source/key/value structs, and probably a useful experiment (:

[KodrAus]

Having some standards around well-known key-value pairs is something I've also been exploring in a little wrapper. It seems like it'll be useful for a more composable logging ecosystem.

[yoshuawuyts]

@KodrAus Yeah for sure! -- I wonder which others to add; I only really thought of spans::{start,end} and http::{request,response}. Though I guess timestamps, host, ip might be common too?

Oh also, I saw femme is not listed yet; could we perhaps add it to the tracking issue?

[atroche]

I'm hesitant to add to the list of todos because I really want this feature, but it might be worth adding fern as another crate to integrate with. I don't use it (I use slog), but it seems like it has quite a lot of usage (600,000+ all time downloads on crates.io).

[MOZGIII]

Should Source::count return a Result<usize> instead of a plain usize?
What if we move the Source::count to a separate trait:

trait SourceCount: Source {
    fn count(&self) -> usize;
}

Rationale is it looks more reasonable to just make it a type-system question whether a certain type has a notion of a count of it's kvs or not.

And if that's not the desired use case for making count return Result<usize> - then what is? What do you see as possible error values? Why not just Option<usize>? Some lazy-evaluated kv sources might not have count known upfront, i.e. something like processes list (ps ax) might be collected on demand.

[KodrAus]

What if we move the Source::count to a separate trait

@MOZGIII unfortunately a separate trait wouldn't really work because we'd lose the implementation when erasing as dyn Source.

What do you see as possible error values?

The desire for Result would just be to be able to pass through any errors from the default implementation that calls the fallible visit_pair method. But Option seems worthwhile!

Some lazy-evaluated kv sources might not have count known upfront

Hmm, I don't think the current implementation really supports this kind of scenario because pairs can be visited and fetched at any point. I also don't think it's really desirable to support either, because pairs may be inspected and visited multiple times any expensive work or externally changing information could be confusing to end consumers.

[MOZGIII]

Given all that, I'm having hard time imagining a case when the count would be None (or Err). Do you have an example in mind?
How is the count used? Is it like iterator's size_hint?

[loganmzz]

Any plan to make this stable ? More than 4 years since issue opening. This feature is mandatory for attaching contextual information to logs (user, error id, use case, etc.) that can then be passed as kv to logging/event ingestion systems (ELK, Loki, InfluxDB, etc.).

Or any workaround ?

[tmccombs]

The workaround is to use the unstable feature, or use the slog crate.

[8573]

tracing is quite popular and was designed for structured logging. It can catch the (unstructured) log events of log and turn them into tracing events. I don't know whether it's more stable than this, though.

[jmjoy]

It is better to have a unified log library. I know that the popular ones are log, slog, and tracing. It is better to add log to the standard library, like log/slog in golang.

[jmjoy]

For structured logging, format strings seem less important, for example:

error!("something failed: {:?}", err);

The following one is better (syntax of tracing):

error!(?err, "something failed");

Forgoing format strings makes macros a lot more pleasant to design.

[KodrAus]

Any plan to make this stable ? More than 4 years since issue opening.

It would be great to have a fresh look at anything blocking this and I can't really think of any left 👍 The macros are a bit rough-and-ready, but I think suitable for most use cases. We really should get this out the door.

Before stabilizing, I think the next step would be running through a full API review with @Thomasdezeeuw, @JohnTitor and anybody else who might want to participate.

For structured logging, format strings seem less important

Yeh, I think the issue here is format args producing a string and throwing away its interpolated arguments. It's nice and intuitive to be able to both describe your event and some of the structured data attached to it using some kind of interpolation. This practice is popular in .NET for example, but Rust's format_args! is just geared towards string construction.

[Thomasdezeeuw]

Any plan to make this stable ? More than 4 years since issue opening.

It would be great to have a fresh look at anything blocking this and I can't really think of any left 👍 The macros are a bit rough-and-ready, but I think suitable for most use cases. We really should get this out the door.

I can only think of two things that we should think about of the top of my head, but neither should block stabilisation:

• Decide if we want to support tracing like short-hand for as_debug! (so ?my_value) and related.
• Integration of serde and sval into the Visit trait. Here is for example a concrete Visit implementation that outputs JSON: https://github.com/Thomasdezeeuw/std-logger/blob/eff67f4c33b89c8debd325c1ad79724e6cd6af2c/src/format/json.rs#L167, but it doesn't handle serde or sval based values.

Before stabilizing, I think the next step would be running through a full API review with @Thomasdezeeuw, @JohnTitor and anybody else who might want to participate.

I can do that next weekend 👍

For structured logging, format strings seem less important

Yeh, I think the issue here is format args producing a string and throwing away its interpolated arguments. It's nice and intuitive to be able to both describe your event and some of the structured data attached to it using some kind of interpolation. This practice is popular in .NET for example, but Rust's format_args! is just geared towards string construction.

Since we're really dependant on rust std lib on this you could ask in rust-lang/rust#99012 for this. Though it might conflict with rust-lang/rust#78356 which was stabilised in 1.71.

[KodrAus]

Decide if we want to support tracing like short-hand for as_debug! (so ?my_value) and related.

I think this is something that would be reasonable to do 👍 tracing has already set a bit of a precedent that would be good to respect.

Integration of serde and sval into the Visit trait.

Ah, I think this highlights one thing we definitely need to work on; documentation. You should be able to support serde or sval in your visit_any implementation. The Value type always implements serde::Serialize or sval::Value when the kv_unstable_serde or kv_unstable_sval features are enabled. So if you add, say, a serde feature to std-logger you should be able to just pass the Value you're given directly to serde_json::to_string and it'll "just work".

Since we're really dependant on rust std lib on this you could ask in rust-lang/rust#99012 for this

Personally, I think it's ok for format_args to optimize for string construction. That lets it consider optimizations like pre-formatting constants that it otherwise couldn't do.

I can do that next weekend 👍

If you have the bandwidth to run over things sometime that would be amazing! I'd be happy to do something a bit more synchronous too or at least do a pass over our docs if that would be helpful?

[Thomasdezeeuw]

I've done a review of the key-value feature in the log crate and opened #584 to discuss some things. Overall I think it looks pretty good and I think we're close to stabilisation. I still want to review the valuebag crate (added dependency), I think I'm going to skip serde and sval as they are much larger and more widely used already.

I've also opened #583 containing some small fixes and additions.

[KodrAus]

Thanks @Thomasdezeeuw!

A good review of value-bag would be much appreciated too. It originally started as the infrastructure here in log, but became a bit heavy so I pulled it out. Its public API is very similar to log::kv::Value. For the review of log::kv itself, maybe we can use #584 so discussion isn't split here?

[Thomasdezeeuw]

@KodrAus I took a look at value-bag (from the perspective of using it in the log crate). Overall I think it looks good 👍

For the capture_* and from_* methods I have the same comment as I made here: #584 (comment) (so let's continue the discussion about this there).

We could get the size down from 3 to 2 words (on 64 bit) by using tagged pointers, but I don't know if that is worth all the unsafe code.

One final note is around the Fill trait, which isn't used by the log crate, but it was a little surprising to me that the Fill::fill method seems to be called multiple times on every access (?). That wasn't clear to me by (quickly) scanning the Fill docs. Maybe a note in the docs would be sufficient.

[scripturial]

We could get the size down from 3 to 2 words (on 64 bit) by using tagged pointers, but I don't know if that is worth all the unsafe code.

Thanks for this work. Looking forward to it being released proper.

Some systems generate a significant amount of log data in debug mode, so it might be worth the effort, but personally I wouldn't want a change at this point to hold up release of this feature. It seems more important that structured logging become a stable feature sooner rather than later.

[zopsicle]

log is used by over 50000 crates, which means you'll inevitably pull it in as a transitive dependency. I'm therefore concerned about value-bag being added as a dependency here. Will this remain an optional, non-default feature?

[Thomasdezeeuw]

log is used by over 50000 crates, which means you'll inevitably pull it in as a transitive dependency. I'm therefore concerned about value-bag being added as a dependency here. Will this remain an optional, non-default feature?

I'm afraid not, it's the core of the Value type (about 50% of this feature ;) )

Maybe we can move it to the rust-lang org? /cc @KodrAus

[KodrAus]

@chloekek I think that's a reasonable concern. In fact, in #613 I've made that dependency fully optional for structured logging, so if you just want to log simple primitives, like numbers, strings, booleans, or formattable values, you won't pull it in.

For some background on what that value-bag library is (as well as a serialization framework called sval), they all started out as the implementation directly here in log, but grew in complexity to a point where it seemed best to split them out. I didn't originally try move them to a repository in the rust-lang organization I think because I didn't want it to carry any sense of being an "official" solution to dynamic values. So I created an organization: https://github.com/sval-rs and it's been living and continuing to evolve there.

I would happily move that repository anywhere or add any collaborators of log to that organization 🙂