Get structured logging API ready for stabilization #613

2024-01-26T02:08:39-06:00

KodrAus commented

2024-01-26 02:08:39 -06:00

(Migrated from github.com)

Closes #149
Closes #328
Closes #357
Closes #436
Closes #584

Based on the review in #584

The plan is to:

Deprecate Value::capture_* and Value::downcast_* methods. All deprecated APIs are gated under the old kv_unstable features and will be removed once we remove those old unstable features.
Fill in the documentation for structured logging support so people can actually use it.
Add some macro syntax for capturing attributes as debug or display instead of the default ToValue (key:? = value).
Only pull in value-bag as a dependency if either serde or sval is also needed. In cases where you just want basic structured logging, we should do it in a dependency-free way. This will just mean adding a simple ValueInner enum.

I'll cc once this is ready for review, to save a bit of notification noise.

Once this PR is complete, we should be able to stabilize structured logging support in the log crate.

Closes #149 Closes #328 Closes #357 Closes #436 Closes #584 Based on the review in #584 The plan is to: - [x] Deprecate `Value::capture_*` and `Value::downcast_*` methods. All deprecated APIs are gated under the old `kv_unstable` features and will be removed once we remove those old unstable features. - [x] Fill in the documentation for structured logging support so people can actually use it. - [x] Add some macro syntax for capturing attributes as debug or display instead of the default `ToValue` (`key:? = value`). - [x] Only pull in `value-bag` as a dependency if either `serde` or `sval` is also needed. In cases where you just want basic structured logging, we should do it in a dependency-free way. This will just mean adding a simple `ValueInner` enum. I'll cc once this is ready for review, to save a bit of notification noise. Once this PR is complete, we should be able to stabilize structured logging support in the `log` crate.

👍 2 ❤️ 1 🎉 1

KodrAus commented

2024-01-28 15:01:01 -06:00

(Migrated from github.com)

We currently have kv::source::Visitor and kv::value::Visit. They're both visitor types (separate because they serve separate purposes), but should probably still be named consistently. @Thomasdezeeuw what do you think? Should we rename either source::Visitor or value::Visit? My preference would be to rename value::Visit to value::Visitor.

We currently have `kv::source::Visitor` and `kv::value::Visit`. They're both visitor types (separate because they serve separate purposes), but should probably still be named consistently. @Thomasdezeeuw what do you think? Should we rename either `source::Visitor` or `value::Visit`? My preference would be to rename `value::Visit` to `value::Visitor`.

Thomasdezeeuw commented

2024-01-29 05:17:21 -06:00

(Migrated from github.com)

We currently have kv::source::Visitor and kv::value::Visit. They're both visitor types (separate because they serve separate purposes), but should probably still be named consistently. @Thomasdezeeuw what do you think? Should we rename either source::Visitor or value::Visit? My preference would be to rename value::Visit to value::Visitor.

I think Visitor is more common? So I would go with that.

I would understand possible confusing between the two traits, so maybe we need to rename one of the two? What about renaming source::Visitor to KeyValuePairs or just KeyValues, to indicate its a collection of key-value pairs?

> We currently have `kv::source::Visitor` and `kv::value::Visit`. They're both visitor types (separate because they serve separate purposes), but should probably still be named consistently. @Thomasdezeeuw what do you think? Should we rename either `source::Visitor` or `value::Visit`? My preference would be to rename `value::Visit` to `value::Visitor`. I think `Visitor` is more common? So I would go with that. I would understand possible confusing between the two traits, so maybe we need to rename one of the two? What about renaming `source::Visitor` to `KeyValuePairs` or just `KeyValues`, to indicate its a collection of key-value pairs?

KodrAus commented

2024-01-29 15:15:20 -06:00

(Migrated from github.com)

I would understand possible confusing between the two traits, so maybe we need to rename one of the two?

That's a fair point. Perhaps we could keep the names verb-y and use VisitSource and VisitValue?

> I would understand possible confusing between the two traits, so maybe we need to rename one of the two? That's a fair point. Perhaps we could keep the names verb-y and use `VisitSource` and `VisitValue`?

Thomasdezeeuw commented

2024-01-30 04:39:28 -06:00

(Migrated from github.com)

That's a fair point. Perhaps we could keep the names verb-y and use VisitSource and VisitValue?

Sounds good 👍

> That's a fair point. Perhaps we could keep the names verb-y and use `VisitSource` and `VisitValue`? Sounds good :+1:

KodrAus commented

2024-01-30 21:31:31 -06:00

(Migrated from github.com)

Ok, I think the last remaining thing here is macro syntax. We could adopt exactly tracing's syntax of:

key = <modifier> arg

where <modifier> may be ? for fmt::Debug or % for fmt::Display. I'm not a huge fan of leaning on sigils, or on prefixed modifiers here, because it leaves us almost no room for extensibility, but does have the benefit of being what's already there. I was thinking something like:

key = arg : <modifier>

where <modifier> may be blank for fmt::Display, ? for fmt::Debug, or the literal text serde or sval for those respective libraries. In practice, it would look something like:

data: captured using ToValue
data:: captured using fmt::Display
data:?: captured using fmt::Debug
data:serde: captured using serde::Serialize
data:sval: captured using sval::Value

We could use a simple lowering scheme so data:? lowered to data:debug and data: lowered to data:display, so it would be less easy to miss the presence of the :.

Another potential position could be on the key name:

key : <modifier> = arg

That would more easily let us expected arg to be a full expression in the future.

Any thoughts?

Ok, I think the last remaining thing here is macro syntax. We could adopt exactly `tracing`'s syntax of: ``` key = <modifier> arg ``` where `<modifier>` may be `?` for `fmt::Debug` or `%` for `fmt::Display`. I'm not a huge fan of leaning on sigils, or on prefixed modifiers here, because it leaves us almost no room for extensibility, but does have the benefit of being what's already there. I was thinking something like: ``` key = arg : <modifier> ``` where `<modifier`> may be blank for `fmt::Display`, `?` for `fmt::Debug`, or the literal text `serde` or `sval` for those respective libraries. In practice, it would look something like: - `data`: captured using `ToValue` - `data:`: captured using `fmt::Display` - `data:?`: captured using `fmt::Debug` - `data:serde`: captured using `serde::Serialize` - `data:sval`: captured using `sval::Value` We could use a simple lowering scheme so `data:?` lowered to `data:debug` and `data:` lowered to `data:display`, so it would be less easy to miss the presence of the `:`. Another potential position could be on the key name: ``` key : <modifier> = arg ``` That would more easily let us expected `arg` to be a full expression in the future. Any thoughts?

Thomasdezeeuw commented

2024-01-31 06:32:40 -06:00

(Migrated from github.com)

key = arg : <modifier>
where <modifier> may be blank for fmt::Display, ? for fmt::Debug, or the literal text serde or sval for those respective libraries. In practice, it would look something like:

I like this, feels similar to write! (and print!, etc.) macros.

* `data:serde`: captured using `serde::Serialize`

* `data:sval`: captured using `sval::Value`

Small thing is versioning, in case serde/sval ever publish a v2, how do we want to handle that? We can go serdeV1 or serde1 or something else with a version in it, but if a v2 never comes it will just be annoying. So maybe serde/sval means v1, and serde2/sval2 could v2?

We could use a simple lowering scheme so data:? lowered to data:debug and data: lowered to data:display, so it would be less easy to miss the presence of the :.

Because we'll be copying the standard formatting found in the std lib, I don't think will become an issue.

Another potential position could be on the key name:
key : <modifier> = arg
That would more easily let us expected arg to be a full expression in the future.

How would be limiting ourselves using the above arg : <modifier>? I suppose we won't be able to support full expressions?

> ``` > key = arg : <modifier> > ``` > > where `<modifier`> may be blank for `fmt::Display`, `?` for `fmt::Debug`, or the literal text `serde` or `sval` for those respective libraries. In practice, it would look something like: I like this, feels similar to `write!` (and `print!`, etc.) macros. > * `data:serde`: captured using `serde::Serialize` > > * `data:sval`: captured using `sval::Value` Small thing is versioning, in case serde/sval ever publish a v2, how do we want to handle that? We can go `serdeV1` or `serde1` or something else with a version in it, but if a v2 never comes it will just be annoying. So maybe `serde`/`sval` means v1, and `serde2`/`sval2` could v2? > We could use a simple lowering scheme so `data:?` lowered to `data:debug` and `data:` lowered to `data:display`, so it would be less easy to miss the presence of the `:`. Because we'll be copying the standard formatting found in the std lib, I don't think will become an issue. > Another potential position could be on the key name: > > ``` > key : <modifier> = arg > ``` > > That would more easily let us expected `arg` to be a full expression in the future. How would be limiting ourselves using the above `arg : <modifier>`? I suppose we won't be able to support full expressions?

KodrAus commented

2024-01-31 15:34:40 -06:00

(Migrated from github.com)

So maybe serde/sval means v1, and serde2/sval2 could v2?

That seems like a good scheme to me 👍 I spelled this out explicitly in value-bag, but it's not really meant to be user-facing. I think it's reasonable to make the "unversioned" ident refer to the current stable versions in log.

How would be limiting ourselves using the above arg : ? I suppose we won't be able to support full expressions?

We'd just need to wrap full expressions in parenthesis or braces, because the : character can't appear directly after an expression in a macro rule.

> So maybe serde/sval means v1, and serde2/sval2 could v2? That seems like a good scheme to me :+1: I spelled this out explicitly in `value-bag`, but it's not really meant to be user-facing. I think it's reasonable to make the "unversioned" ident refer to the current stable versions in `log`. > How would be limiting ourselves using the above arg : <modifier>? I suppose we won't be able to support full expressions? We'd just need to wrap full expressions in parenthesis or braces, because the `:` character can't appear directly after an expression in a macro rule.

👍 1

KodrAus commented

2024-02-13 04:33:41 -06:00

(Migrated from github.com)

This is quite a big change but I think it's ready for a review now. Some things to call out:

The macro syntax I ended up with was key:modifier = value, so key:? = value for debug for instance. This was easier to implement and didn't require breaking any existing users.
Should we make the kv::source and kv::value modules private now there's no types in them that aren't exported in the root kv module? I think we probably should.

This is quite a big change but I think it's ready for a review now. Some things to call out: - The macro syntax I ended up with was `key:modifier = value`, so `key:? = value` for debug for instance. This was easier to implement and didn't require breaking any existing users. - Should we make the `kv::source` and `kv::value` modules private now there's no types in them that aren't exported in the root `kv` module? I think we probably should.

👍 1

Thomasdezeeuw (Migrated from github.com) approved these changes

2024-02-13 05:20:30 -06:00

Thomasdezeeuw (Migrated from github.com) left a comment

I like it.

The only concern I have is that people find the modified on the key odd/unexpected, when coming from the std::fmt implementation. That might be worth calling out in the documentation.

I like it. The only concern I have is that people find the modified on the key odd/unexpected, when coming from the `std::fmt` implementation. That might be worth calling out in the documentation.

Cargo.toml

					
				@ -46,25 +46,31 @@ release_max_level_trace = []

				std = []

More a question about Cargo I suppose, but does enabling kv_unstable_{sval,std,serde} also add value-bag as a dependency due to the enabling of `"value-bag/{sval,error,serde}"?

More a question about Cargo I suppose, but does enabling `kv_unstable_{sval,std,serde}` also add `value-bag` as a dependency due to the enabling of `"value-bag/{sval,error,serde}"?

src/__private_api.rs

					
				@ -87,3 +82,44 @@ pub fn log<'a, K>(

				pub fn enabled(level: Level, target: &str) -> bool {

				    crate::logger().enabled(&Metadata::builder().level(level).target(target).build())

				}

Why the double reference?

src/kv/mod.rs

					
				@ -13,0 +8,4 @@

				//! features = ["kv"]

				//! ```

				//!

				//! # Structured logging in `log`

//! attributes. Structured logs can be analyzed using a variety of traditional

Or I think the word can be removed entirely.

```suggestion //! attributes. Structured logs can be analyzed using a variety of traditional ``` Or I think the word can be removed entirely.

I like this 👍

I like this :+1:

Nit: want to move this above the info! statement so they stay in sync?

Nit: want to move this above the `info!` statement so they stay in sync?

I think we'll want to show this in the example so that people understand they need to implement/derive serde::Serialize for log (and serde_json::to_string)

I think we'll want to show this in the example so that people understand they need to implement/derive `serde::Serialize` for log (and `serde_json::to_string`)

Nit: maybe?

//! through `sval` without losing any structure or data.

Nit: maybe? ```suggestion //! through `sval` without losing any structure or data. ```

I would also show this in the example.

src/kv/mod.rs

					
				@ -13,0 +87,4 @@

				//! struct Collect<'kvs>(BTreeMap<Key<'kvs>, Value<'kvs>>);

				//!

				//! impl<'kvs> VisitSource<'kvs> for Collect<'kvs> {

				//!     fn visit_pair(&mut self, key: Key<'kvs>, value: Value<'kvs>) -> Result<(), kv::Error> {

Nit: maybe add assert_eq!(a, Value::from(1)); to make it super clear?

Nit: maybe add `assert_eq!(a, Value::from(1));` to make it super clear?

src/kv/source.rs

					
				@ -10,1 +12,4 @@

				/// Use the [`VisitSource`](trait.VisitSource.html) trait to inspect the structured data

				/// in a source.

				///

				/// A source is like an iterator over its key-values, except with a push-based API

Nit: don't think it's needed any more. But if we have it in other places, then let's leave it and do it some other time for all links.

/// Use the [`VisitSource`] trait to inspect the structured data

Nit: don't think it's needed any more. But if we have it in other places, then let's leave it and do it some other time for all links. ```suggestion /// Use the [`VisitSource`] trait to inspect the structured data ```

src/kv/source.rs

					
				@ -34,15 +74,14 @@ pub trait Source {

				        get_default(self, key)

Nit.

    /// A subsequent call to `visit` should yield the same number of key-values.

Nit. ```suggestion /// A subsequent call to `visit` should yield the same number of key-values. ```

KodrAus (Migrated from github.com) reviewed

2024-02-15 22:54:05 -06:00

Cargo.toml

					
				@ -46,25 +46,31 @@ release_max_level_trace = []

				std = []

It will, yes 👍 We technically don't need value-bag for capturing std::error::Errors, but do for serde or sval.

It will, yes :+1: We technically don't need `value-bag` for capturing `std::error::Error`s, but do for `serde` or `sval`.

KodrAus (Migrated from github.com) reviewed

2024-02-15 23:00:12 -06:00

src/kv/source.rs

					
				@ -10,1 +12,4 @@

				/// Use the [`VisitSource`](trait.VisitSource.html) trait to inspect the structured data

				/// in a source.

				///

				/// A source is like an iterator over its key-values, except with a push-based API

Good call. I think I still need to do a pass over links and make sure they're all resolved correctly so will simplify them wherever possible.

KodrAus (Migrated from github.com) reviewed

2024-02-15 23:10:48 -06:00

src/__private_api.rs

					
				@ -87,3 +82,44 @@ pub fn log<'a, K>(

				pub fn enabled(level: Level, target: &str) -> bool {

				    crate::logger().enabled(&Metadata::builder().level(level).target(target).build())

				}

I left a comment in the source on why we do this. It's just so we can capture T: ?Sized while still erasing it behind a dyn Trait. Passing in the double reference in just helps the lifetimes work out.

I left a comment in the source on why we do this. It's just so we can capture `T: ?Sized` while still erasing it behind a dyn Trait. Passing in the double reference in just helps the lifetimes work out.

KodrAus commented

2024-02-15 23:18:02 -06:00

(Migrated from github.com)

The

err:error = err

way of capturing an error using the std::error::Error trait is maybe something we can improve on someday 🙂

The ``` err:error = err ``` way of capturing an error using the `std::error::Error` trait is maybe something we can improve on someday 🙂

KodrAus commented

2024-02-15 23:19:17 -06:00

(Migrated from github.com)

I think the last thing remaining here is what to do about the _unstable suffix on our features. I was thinking making them just shims for the unsuffixed versions, but continuing to accept them so that we don't break every current user of the feature. What do you think @Thomasdezeeuw?

I think the last thing remaining here is what to do about the `_unstable` suffix on our features. I was thinking making them just shims for the unsuffixed versions, but continuing to accept them so that we don't break every current user of the feature. What do you think @Thomasdezeeuw?

Thomasdezeeuw (Migrated from github.com) approved these changes

2024-02-16 04:24:52 -06:00

Thomasdezeeuw (Migrated from github.com) left a comment

I think the last thing remaining here is what to do about the _unstable suffix on our features. I was thinking making them just shims for the unsuffixed versions, but continuing to accept them so that we don't break every current user of the feature. What do you think @Thomasdezeeuw?

We can, but we a also have other breakages, e.g. the removal of the as_{display,debug, etc.} macros. Some of the API on Value has changes, which is also breaking.

So I'm wondering if we should keep some of the old API, if possible, if kv_unstable is used? Marking it all as deprecated show it at least generates warnings (I don't know if that is possible for features). Then e.g. 6 months after the stable release we can remove the _unstable feature and all it's related API? This would give people some time to migrate their code.

> I think the last thing remaining here is what to do about the `_unstable` suffix on our features. I was thinking making them just shims for the unsuffixed versions, but continuing to accept them so that we don't break every current user of the feature. What do you think @Thomasdezeeuw? We can, but we a also have other breakages, e.g. the removal of the `as_{display,debug, etc.}` macros. Some of the API on `Value` has changes, which is also breaking. So I'm wondering if we should keep some of the old API, if possible, if `kv_unstable` is used? Marking it all as deprecated show it at least generates warnings (I don't know if that is possible for features). Then e.g. 6 months after the stable release we can remove the `_unstable` feature and all it's related API? This would give people some time to migrate their code.

.github/workflows/main.yml

					
				@ -48,3 +47,1 @@

				    - run: cargo test --verbose --features kv_unstable_sval

				    - run: cargo test --verbose --features kv_unstable_serde

				    - run: cargo test --verbose --features "kv_unstable kv_unstable_std kv_unstable_sval kv_unstable_serde"

				    - run: cargo test --verbose --features kv

We could start using cargo-hack for this at some point (for another pr).

We could start using [cargo-hack](https://crates.io/crates/cargo-hack) for this at some point (for another pr).

Cargo.toml

				`@ -46,25 +46,31 @@ release_max_level_trace = []`

To bad there is only compile_error!, not compile_warn! otherwise it would be nice to add that.

To bad there is only `compile_error!`, not `compile_warn!` otherwise it would be nice to add that.

Actually on second though... we're going to break a lot of (unstable) code already by removing the as_serde macros, do we just rip the bandaid in one go and break everything? Or should we add those macros back if [kv_unstable] is used (and mark them as #[deprecated])?

Actually on second though... we're going to break a lot of (unstable) code already by removing the `as_serde` macros, do we just rip the bandaid in one go and break everything? Or should we add those macros back if [`kv_unstable`] is used (and mark them as `#[deprecated]`)?

KodrAus (Migrated from github.com) reviewed

2024-02-16 17:02:59 -06:00

Cargo.toml

				`@ -46,25 +46,31 @@ release_max_level_trace = []`

I think this is a reasonable thing to do 👍

Unfortunately you can’t mark them as deprecated but we can also re-export the renamed visitor traits under their old names when the old _unstable features are enabled.

I think this is a reasonable thing to do :+1: Unfortunately you can’t mark them as deprecated but we can also re-export the renamed visitor traits under their old names when the old `_unstable` features are enabled.

KodrAus commented

2024-02-17 17:44:04 -06:00

(Migrated from github.com)

How does this sound as a plan for stabilization:

Keep all old APIs when the kv_unstable feature is enabled, deprecating wherever possible.
Set a time period where we’ll remove the kv_unstable feature altogether and all those deprecated items. If we keep rough tabs on public code using the old features then we could get some idea of when would be a good time to do this.

The idea being new code and any maintained in that time period should move from the unstable to the stable API without much fuss, but there will be a point where the bandaid comes off completely. The only unfortunate part is we can’t deprecate old trait names so we don’t have a good way of making users of them aware things have changed.

How does this sound as a plan for stabilization: 1. Keep all old APIs when the `kv_unstable` feature is enabled, deprecating wherever possible. 2. Set a time period where we’ll remove the `kv_unstable` feature altogether and all those deprecated items. If we keep rough tabs on public code using the old features then we could get some idea of when would be a good time to do this. The idea being new code and any maintained in that time period should move from the unstable to the stable API without much fuss, but there will be a point where the bandaid comes off completely. The only unfortunate part is we can’t deprecate old trait names so we don’t have a good way of making users of them aware things have changed.

Thomasdezeeuw commented

2024-02-18 04:37:41 -06:00

(Migrated from github.com)

How does this sound as a plan for stabilization:

Sounds good to me 👍

> How does this sound as a plan for stabilization: Sounds good to me :+1:

KodrAus commented

2024-02-18 15:37:49 -06:00

(Migrated from github.com)

In this latest round of changes I've restored the old APIs under their respective *_unstable feature flags and added support for shorthand capturing, so instead of having to write info!(a = a; "") you can write info!(a; "").

In this latest round of changes I've restored the old APIs under their respective `*_unstable` feature flags and added support for shorthand capturing, so instead of having to write `info!(a = a; "")` you can write `info!(a; "")`.

KodrAus commented

2024-02-18 16:04:17 -06:00

(Migrated from github.com)

Ok, I think this is ready for its last review now. Thank you so much for all the time you've invested in helping push this forwards so far @Thomasdezeeuw 🙏 We'd never have reached this point without you.

👍 1

Thomasdezeeuw (Migrated from github.com) approved these changes

2024-02-19 14:24:56 -06:00

Thomasdezeeuw (Migrated from github.com) left a comment

Nice! Let's merge.

I'm gonna go over the API with https://github.com/Enselic/cargo-public-api/ see what, if any, difference there are

Nice! Let's merge. I'm gonna go over the API with https://github.com/Enselic/cargo-public-api/ see what, if any, difference there are

README.md

					
				@ -110,3 +113,4 @@

				    trace!(target = "yak_events", yak:serde; "Commencing yak shaving");

				    loop {

				        match find_a_razor() {

Nit: maybe this makes the example a little confusing? Making it look like : is the separator for key-value pairs?

Nit: maybe this makes the example a little confusing? Making it look like `:` is the separator for key-value pairs?

Thomasdezeeuw (Migrated from github.com) reviewed

2024-02-19 14:43:06 -06:00

Cargo.toml

				`@ -46,25 +46,31 @@ release_max_level_trace = []`

I think we need to enable these features.

kv_unstable = ["kv", "value-bag"]
kv_unstable_sval = ["kv_sval", "kv_unstable"]
kv_unstable_std = ["kv_std", "kv_unstable"]
kv_unstable_serde = ["kv_serde", "kv_unstable_std"]

This resolved most of the compilation errors for my crate, except for one. It can't find log::kv::value::Visit.

I think we need to enable these features. ```suggestion kv_unstable = ["kv", "value-bag"] kv_unstable_sval = ["kv_sval", "kv_unstable"] kv_unstable_std = ["kv_std", "kv_unstable"] kv_unstable_serde = ["kv_serde", "kv_unstable_std"] ``` This resolved most of the compilation errors for my crate, except for one. It can't find `log::kv::value::Visit`.

src/kv/value.rs

					
				@ -765,13 +596,586 @@ where

				    }

Should this be visit?

pub use VisitValue as Visit;

Should this be visit? ```suggestion pub use VisitValue as Visit; ```

KodrAus (Migrated from github.com) reviewed

2024-02-19 15:31:43 -06:00

README.md

					
				@ -110,3 +113,4 @@

				    trace!(target = "yak_events", yak:serde; "Commencing yak shaving");

				    loop {

				        match find_a_razor() {