Allow macros to be more consistent with kvs

[KodrAus]

Part of #436

This tweaks the new key-value macro syntax slightly so that it can be more consistent in cases where key-values are supplied and in cases where they're not. All the old syntax is still supported, but we can now write log! macros like:

info!(target = "my_target"; "format {string}");

which then supports key-value pairs as:

info!(target = "my_target"; key1 = value1, key2 = value2; "format {formatted1}", formatted1 = value1);

For key-values, the target = x; form is required. It splits our macro up into 3 logical parts, separated by ;s:

1. target = "my_target": The portion of the log record that's considered by top-level filtering. It's equivalent to log_enabled!.
2. key1 = value1, key2 = value2: The structured data associated with the log record.
3. "format {formatted1}", formatted1 = value1: The unstructured message associated with the log record.

I think for log here we should also remove the capture_* methods on Value for now, because they lead to unpleasant compilation errors when you don't have a &T: 'static around. They're only useful if you want to try downcast to a specific type, like a Uuid or Timestamp.

I'll try flesh out our test coverage even more, since there are a lot of possible permutations of the log macros and their interactions with format_args to consider.

cc @Thomasdezeeuw. What do you think?

[Thomasdezeeuw]

Part of #436

This tweaks the new key-value macro syntax slightly so that it can be more consistent in cases where key-values are supplied and in cases where they're not. All the old syntax is still supported, but we can now write log! macros like:

info!(target = "my_target"; "format {string}");

which then supports key-value pairs as:

info!(target = "my_target"; key1 = value1, key2 = value2; "format {formatted1}", formatted1 = value1);

For key-values, the target = x; form is required. It splits our macro up into 3 logical parts, separated by ;s:

1. `target = "my_target"`: The portion of the log record that's considered by top-level filtering. It's equivalent to `log_enabled!`.

2. `key1 = value1, key2 = value2`: The structured data associated with the log record.

3. `"format {formatted1}", formatted1 = value1`: The unstructured message associated with the log record.

Did target: x not work? That is what is currently used.

I think for log here we should also remove the capture_* methods on Value for now, because they lead to unpleasant compilation errors when you don't have a &T: 'static around. They're only useful if you want to try downcast to a specific type, like a Uuid or Timestamp.

And replace them with the from_display! macros?

[KodrAus]

Did target: x not work? That is what is currently used.

It does work, but when I started using it I found the inconsistency with key values and named format args a bit jarring. We’ll probably want some err = expr syntax too at some point so thought starting to try normalize everything would be good.

And replace them with the from_display! macros?

Those methods and direct downcasting will just go away, unless it’s something you’re currently using? Speaking of, what do you think of those little macros? The alternative is something like tracing’s flags, which are similar to format_args.

[Thomasdezeeuw]

Did target: x not work? That is what is currently used.

It does work, but when I started using it I found the inconsistency with key values and named format args a bit jarring. We’ll probably want some err = expr syntax too at some point so thought starting to try normalize everything would be good.

I'm not sure. One the one hand I can see your argument, on the other target it is different from the key-values as it has its own method to access it (not via Record::key_values, but via Record::target). Being inconsistent with the non-kvs macros could be annoying. For example when you quickly want to add a kv pair to a message you now also have to consider the target. But I don't know how munch of an annoyance that will be.

And replace them with the from_display! macros?

Those methods and direct downcasting will just go away, unless it’s something you’re currently using?

I do use the downcasting but I'll switch to the visitor API introduces in #467, so a nice deprecation period would be appreciated.

Speaking of, what do you think of those little macros? The alternative is something like tracing’s flags, which are similar to format_args.

I could either way. The way the tracing crate does is a bit unusual on first sight, but I image you get used to it. So it's a question of being more explicit (macros) vs quicker to write (tracing like flags). I'm with either.

[KodrAus]

I do use the downcasting but I'll switch to the visitor API

Ah that's right, you've been forced to use a nasty chain of if lets haven't you because that visitor API wasn't available. I'll make sure it doesn't disappear on you in the meantime.

when you quickly want to add a kv pair to a message you now also have to consider the target.

You can still specify key-value pairs without having to specify a target:

info!(cat_1 = "chashu", cat_2 = "nori", cat_count = 2; "hello {world}", world = "world");

...but that does raise an interesting forwards compatibility hazard. Say you write:

info!(target = "kv_target", cat_1 = "chashu", cat_2 = "nori"; "hello {}", "world");

In this scheme, that target will end up as a key-value pair instead of as the target. Since we then default the target to module_path!() you'll end up with record.target() returning something else. This is solvable with a bit more macro work.

The way the tracing crate does is a bit unusual on first sight, but I image you get used to it.

Yeh, I think once you learn the scheme it's not too bad. My main reason not for trying to pursue it here is that I think formatting flags are a bit of a dead end. They're crafted for the needs of format_args, but once we're outside their use-case we need to pick new arbitrary characters for new things, like capturing with serde, and those new things don't necessarily integrate with any other flags (what would it mean to capture with serde and also pad with spaces?). But if we want to come up with a nice shorthand scheme we could deprecate these as_* macros pretty easily.

I don't want to keep you blocked on this for much longer though, so maybe after we're sure we're not painted into any corners (which I don't think we are this time) we can create a bit of a checklist on #343 of incomplete parts in the macros so they don't need to hold up getting something out?

[Thomasdezeeuw]

when you quickly want to add a kv pair to a message you now also have to consider the target.

You can still specify key-value pairs without having to specify a target:

info!(cat_1 = "chashu", cat_2 = "nori", cat_count = 2; "hello {world}", world = "world");

I meant going from a log with a target to a log with a target and key-values, for example:

// Original:
info!(target: "yak_events", "Commencing yak shaving for {:?}", yak);

// New
info!(target: "yak_events", key = value; "Commencing yak shaving for {:?}", yak); // This won't work.
info!(target = "yak_events", key = value; "Commencing yak shaving for {:?}", yak); // This will.

Or am I mistaken here?

...but that does raise an interesting forwards compatibility hazard. Say you write:

info!(target = "kv_target", cat_1 = "chashu", cat_2 = "nori"; "hello {}", "world");

In this scheme, that target will end up as a key-value pair instead of as the target. Since we then default the target to module_path!() you'll end up with record.target() returning something else. This is solvable with a bit more macro work.

I was saying it could be confusing. With your example above it's not clear that target is "special" (in the sense it can be retrieved using Record.target instead of being another key-value pair). Keeping the ":" syntax might make it clearer?

And it allows people to use target as a key in a key-value pair.

The way the tracing crate does is a bit unusual on first sight, but I image you get used to it.

Yeh, I think once you learn the scheme it's not too bad. My main reason not for trying to pursue it here is that I think formatting flags are a bit of a dead end. They're crafted for the needs of format_args, but once we're outside their use-case we need to pick new arbitrary characters for new things, like capturing with serde, and those new things don't necessarily integrate with any other flags (what would it mean to capture with serde and also pad with spaces?). But if we want to come up with a nice shorthand scheme we could deprecate these as_* macros pretty easily.

👍

I don't want to keep you blocked on this for much longer though, so maybe after we're sure we're not painted into any corners (which I don't think we are this time) we can create a bit of a checklist on #343 of incomplete parts in the macros so they don't need to hold up getting something out?

I think the only decision we need to make is for taget ":" vs "=". We can use macros for formatting and add special tracing-like flags later without breaking compatibility right?

[KodrAus]

Sounds good 👍

I’m not too strongly tied to my = preference, possibly because I just don’t ever set target myself when logging. We could accept both forms still if we wanted to. I was thinking of working towards unifying key values with other pieces of metadata we associate with a log record so there isn’t a distinction in the end between target and anything else.

I would be ok with keeping target using : and deprecate it by making a key-value pair called target just work in the future.

[Thomasdezeeuw]

Sounds good 👍

I’m not too strongly tied to my = preference, possibly because I just don’t ever set target myself when logging. We could accept both forms still if we wanted to. I was thinking of working towards unifying key values with other pieces of metadata we associate with a log record so there isn’t a distinction in the end between target and anything else.

I would be ok with keeping target using : and deprecate it by making a key-value pair called target just work in the future.

Sounds good. I think for backwards compatibility we want to keep : for now.

[KodrAus]

Ok, I've reverted the need to make use the target = form in kv-enabled macros to avoid churning things. We can now technically write this though:

info!(target = "my_target", cat_1 = "chashu", cat_2 = "nori", cat_count = 2; "hello {}", "world");

In this case we'll interpret target as a key-value pair. This is how I think we'll be able to get away from target: in the future, by making the macro effectively:

$lvl:expr, $($key:ident = $value:expr),+; $($arg:tt)+

where we can use a tt-muncher to unpack the key-value pairs and pick off a target, error etc if we find them, but don't have any special syntax for declaring them apart from any other piece of data you might want to associate with your record.

Once this is green I'll merge it in and give it a smoke test in any candidate libraries to make sure it doesn't regress things and then get it out the door.