key_value capable log macros

[yoshuawuyts]

Continuation of #328 (comment).

Description

kv_unstable is available in log and provides a key_values field on the Record to capture key-value pairs. However currently in order to write data to loggers Record types need to be constructed manually, rather than being able to use the log macros. As per RFC#296 we should experiment with logging macros out of tree, and use it to inform how to add key-value logging to log's macros.

Constraints

[tbi]

@KodrAus could you perhaps clarify what the constraints are?

Prior Art

Slog

The slog crate uses ;"key" => "value" pairs in the macros:

#[macro_use]
extern crate slog;

fn main() {
    let drain = slog::Discard;
    let root = slog::Logger::root(
        drain,
        o!("key1" => "value1", "key2" => "value2")
    );
    info!(root, "test info log"; "log-key" => true);
}

Tracing

tracing supports two kinds of log styles: "a message + key-value pairs", and "only key-value pairs":

use tracing::field;

let addr = Ipv4Addr::new(127, 0, 0, 1);
let conn = Connection { port: 40, speed: 3.20 };

info!({ port = conn.port }, "connected to {}", addr);
info!(
    target: "connection_events",
    ip = %addr,
    conn.port,
    ?conn.speed,
);

Update this section with more examples

Creating a manual record

For reference, this is how to create a manual record with key-value pairs:

use log::kv::{Error, Visitor, Source};

struct Pair {
    val: String
}

impl Source for Pair {
    fn visit(&self, visitor: &mut dyn Visitor<'_>) -> Result<(), Error> {
        visitor.visit_pair("some key".into(), self.val.into())
    }
}

log::logger().log(&log::Record::builder()
    .args(format_args!("hello world!"))
    .key_values(&Pair { val: "some value".to_string() })
    .level(log::Level::Info)
    .target(module_path!())
    .module_path(Some(module_path!()))
    .file(Some(file!()))
    .line(Some(line!()))
    .build());

Conclusion

We should experiment with logging macros that can capture key-value pairs and report back with our findings in this issue. It'd be great if we could discuss their tradeoffs, and eventually come up with a design that's suitable for an RFC.

[Thomasdezeeuw]

Just an idea for alternative syntax: adding bracket around the key value pairs:

info(target: "some target", "some message: {}", msg_arg, {
    // And the one of the following.
    key1: value1,
    key1 = value1,
    key1 => value1,
})

Hopefully something like this will aid in formatting long lines, although I'm not sure how rustfmt would handle this.

[KodrAus]

I think our only real constraint is that existing log! statements should continue to work.

I was thinking about capturing key-value pairs implicitly from the format, so if they appear in the message then they appear as key-value pairs:

info!("connected to {service} at {uri}", service, uri);

however that could be a breaking change and would require procedural macro support.

There are other things the macros could do, like allow you to capture a std::error::Error explicitly in the warn! and error! macros.

[yoshuawuyts]

I've been thinking about this for a bit, and I think I like the direction @Thomasdezeeuw's proposed quite a lot. Specifically using : to create struct-like fields:

Example

info!("hello {}", "cats", {
    cat_1: "chashu",
    cat_2: "nori",
});

Something I particularly like about this is that it feels similar to the way we initialize structs right now. Except they're anonymous, and placed in-line.

Also I think the key-values should only be valid as the final argument to log macro invocations. I've been taking a closer look at existing alternatives lately, and it seems that at least some implementations allow key-values to be passed in multiple positions which has felt somewhat confusing to me.

Argument Detection

@KodrAus I've been thinking a about what you've proposed for a bit, and a problem I see is that while it makes it convenient to add kv arguments to the messages, it becomes problematic when certain arguments should not appear as key-value arguments.

I think it slightly boils down to a question of control. By manually passing arguments as key-value we optimize for control, at the expense of some convenience. But given how universal and flexible the log crate needs to be, I think that might be the right tradeoff here.

Though I'm keen to hear more about the automatic error capturing in macros? What would do you think that should look like? Are there perhaps experiments we could do with this?

Implementation

@Thomasdezeeuw would you be interested in writing a prototype of the key-value enabled log macros? If you don't have the time, perhaps @KodrAus or I could also take a shot at it, but it might perhaps be a bit longer (I'm for sure running at capacity right now).

---

I'm very excited about this overall; I've been using this feature in a few projects (including gotten a logger running in the browser w/ wasm) and it's been great! Thanks!

[Thomasdezeeuw]

@yoshuawuyts I'm not great at macros, but I'm willing to give a shot.

[Thomasdezeeuw]

I didn't get very far, see #346, I couldn't fix the ambiguity error. Maybe someone with a bit more Rust macro powers can?

[dtolnay]

Here is a proof of concept of @yoshuawuyts's preferred syntax as a tt muncher:

#[macro_export]
macro_rules! info {
    // info!("...")
    ($e:expr) => {
        $crate::info_impl!(($e));
    };

    // info!("...", args...)
    ($e:expr, $($rest:tt)*) => {
        $crate::info_impl!(($e) $($rest)*);
    };
}

#[macro_export]
#[doc(hidden)]
macro_rules! info_impl {
    // End of macro input
    (($($e:expr),*)) => {
        println!("msg={:?}", format!($($e),*));
    };

    // Trailing k-v pairs containing no trailing comma
    (($($e:expr),*) { $($key:ident : $value:expr),* }) => {
        println!("msg={:?}", format!($($e),*));
        $(
            println!("  {}={:?}", stringify!($key), $value);
        )*
    };

    // Trailing k-v pairs with trailing comma
    (($($e:expr),*) { $($key:ident : $value:expr,)* }) => {
        $crate::info_impl!(($($e),*) { $($key : $value),* });
    };

    // Last expression arg with no trailing comma
    (($($e:expr),*) $arg:expr) => {
        $crate::info_impl!(($($e,)* $arg));
    };

    // Expression arg
    (($($e:expr),*) $arg:expr, $($rest:tt)*) => {
        $crate::info_impl!(($($e,)* $arg) $($rest)*);
    };
}

fn main() {
    info!("hello");
    info!("hello",);
    info!("hello {}", "cats");
    info!("hello {}", "cats",);
    info!("hello {}", "cats", {
        cat_1: "chashu",
        cat_2: "nori",
    });
}

[Thomasdezeeuw]

@dtolnay that is awesome!

Is this the format we want to use?

[KodrAus]

Thanks @dtolnay!

@Thomasdezeeuw for the log crate itself I'd be on board with this syntax 👍 I don't think it breaks any existing consumers because the { $key = $value } matcher won't compile currently and something like info!("hello {}", { "cats" }); would continue to work as expected.

[dtolnay]

Future extensions I think we'll likely want:

• Field init shorthand (just like Field init shorthand rfcs#1682):

  let cat_1 = "chashu";
  let cat_2 = "nori";
  info!("hello {}", "cats", { cat_1, cat_2 });

• Conditional compilation support:

  info!("hello {}", "cats", {
      cat_1: "chashu",
      #[cfg(feature = "both_cats")]
      cat_2: "nori",
  });

[theduke]

A few additional things to consider:

• Literal strings as keys should definitely be supported, in case you need a non-identifier key (other languages, ...). This should not be a problem for the proposed syntax thanks to the :literal macro fragment.

• Maybe: dynamic keys?
  like: let key = format!("xyz{}", x); info!({ #key : 42 })

• Runtime-conditional keys in addition to compile-time conditionals (#[cfg(...)]).
  This could potentially be supported by "splatting" in a <K, V, T: IntoIter<Item = (K, V)>
  Something like: info!({ a: 33, ..map }) (this could potentially also replace the dynamic keys above)

[yoshuawuyts]

Yay, got a full impl working based on @dtolnay's parser, @Thomasdezeeuw's API proposal, and @hawkw's pointers on how the tracing's macros work!

• https://github.com/yoshuawuyts/kv-log-macro

The impl is modeled after log's internals, which means I can easily file a PR to add it log directly (similar to #346), which I'll do next. Thanks heaps everyone -- very excited this is working!!

Usage

use kv_log_macro::info;

fn main() {
    femme::start(log::LevelFilter::Info).unwrap();
    info!("hello");
    info!("hello",);
    info!("hello {}", "cats");
    info!("hello {}", "cats",);
    info!("hello {}", "cats", {
        cat_1: "chashu",
        cat_2: "nori",
    });
}

Screenshot

[Ophirr33]

Took a stab at updating the macro to work with named args, but no luck. I think there's something subtle about matching on something as an expression, and then trying to match on it as a token. Expanding tests/macros.rs on the kv_macro branch shows the following expanded code:

fn with_named_args() {
    let cats = "cats";
    {
        let lvl = ::log::Level::Info;
        if lvl <= ::log::STATIC_MAX_LEVEL && lvl <= ::log::max_level() {
            ::log::__private_api_log(
                ::core::fmt::Arguments::new_v1(
                    &["hello "],
                    &match (&(cats = cats),) {
                        (arg0,) => [],
                    },
                ),
                lvl,
                &("macros", "macros", "tests/macros.rs", 33u32),
                None,
            );
        }
    };
    // skipping others
}

And expanding on master shows the following:

fn with_named_args() {
    let cats = "cats";
    {
        let lvl = ::log::Level::Info;
        if lvl <= ::log::STATIC_MAX_LEVEL && lvl <= ::log::max_level() {
            ::log::__private_api_log(
                ::core::fmt::Arguments::new_v1(
                    &["hello "],
                    &match (&cats,) {
                        (arg0,) => [::core::fmt::ArgumentV1::new(
                            arg0,
                            ::core::fmt::Display::fmt,
                        )],
                    },
                ),
                lvl,
                &("macros", "macros", "tests/macros.rs", 33u32),
            );
        }
    };
   // skipping others
}

The entire named argument expression is being matched on, as opposed to just the actual value. Not sure what to make of that, but I assume it's because matching on foo = foo as a tt results in a different outcome than matching on it as an expr and then matching on it as a tt.

If I add a stringify call, it looks like format_args is being called the same in both contexts.
kv_macro branch:

fn with_named_args() {
    let cats = "cats";
    {
        let lvl = ::log::Level::Info;
        let _as_string1 = "__log_format_args ! (\"hello {cats}\", cats = cats)";
        if lvl <= ::log::STATIC_MAX_LEVEL && lvl <= ::log::max_level() {
            ::log::__private_api_log(
                ::core::fmt::Arguments::new_v1(
                    &["hello "],
                    &match (&(cats = cats),) {
                        (arg0,) => [],
                    },
                ),
                lvl,
                &("macros", "macros", "tests/macros.rs", 33u32),
                None,
            );
        }
    };
}

master:

fn with_named_args() {
    let cats = "cats";
    {
        let lvl = ::log::Level::Info;
        if lvl <= ::log::STATIC_MAX_LEVEL && lvl <= ::log::max_level() {
            let _as_string = "__log_format_args ! (\"hello {cats}\", cats = cats)";
            ::log::__private_api_log(
                ::core::fmt::Arguments::new_v1(
                    &["hello "],
                    &match (&cats,) {
                        (arg0,) => [::core::fmt::ArgumentV1::new(
                            arg0,
                            ::core::fmt::Display::fmt,
                        )],
                    },
                ),
                lvl,
                &("macros", "macros", "tests/macros.rs", 33u32),
            );
        }
    };
}

[KodrAus]

We’ve taken another look at this in #461. The syntax is a strict addition to the existing macros to try avoid some of the pitfalls of forwarding directly to format_args, but should still get a good amount of testing before we release it, and explore any other complimentary syntaxes that could also be added.

[KodrAus]

The new syntax uses a ; to separate arguments attached as context to the record from arguments that make up the message string. We can think of any of these arguments as an implementation detail of producing the message, so they’re not visible to the record itself. This is bound to create repetition, but I think it strikes a fair balance given the compatibility constraints we’re currently working with.

[KodrAus]

cc @rust-lang/libs it would be great to get some input on where things will be at with key-value support in the log! macros after #476. I've got a bit of a plan for consolidating the context we associate with a record as key-value pairs, but since the macro design space is so wide and once we pick a direction we're a bit locked in, I'd appreciate a good sanity check.

Goal

Work towards a consistent log! macro when a combination of target, key-values, and interpolated args is used.

Plan

Currently, the log! macros are a mishmash of different syntaxes and semantics. I'd like to try unify things and reduce the number of unique concepts as much as possible, without creating too much of a leap from println! to log!.

If you take a statement like this:

eprintln!("Something happened! {:?}", err);

You can reroute that to a different target using log! without changing anything except the macro name:

error!("Something happened! {:?}", err);

This works for any level of complexity in the format args:

error!("Something happened! {err:?}", err = e);

One of the benefits of replacing println!s with log!s is that you also get a chance to filter messages before they reach their eventual destination. Every record emitted by log! comes with a target, which you can also set to a static string directly using field-value syntax:

error!(target: "my_target", "Something happened! {err:?}", err = e);

This is the first inconsistency in the macro syntax. The target field uses field-value syntax, while the interpolated err uses assignment syntax. We could argue that target is a field of the Record produced by the macro so should be assigned using that syntax, but you as the producer and caller of error! don't see or interact with any Records. That distinction doesn't seem like a valid one to draw. As the producer, you just have access to some context at the callsite that you want to emit to some outside observer. The only reason we make it is because arguments like err in the example above are interpolated directly into the format. If we wrote:

error!("Something happened at {target}", target = "my_target");

then we wouldn't ever see my_target as a value for target. All we'd see is an anonymous format string that can be written out as Something happened at my_target.

We can't change the assignment syntax because that's what the underlying format_args! macro uses. So for that reason, key-value pairs re-use assignment syntax. If we wanted to make that target visible outside of the format string we could write:

error!(target = "my_target"; "Something happened at {target}", target = "my_target");

Now we have two problems:

1. We have to repeat the target in both the key-values and in the format string.
2. That target = "my_target" isn't the same as target: "my_target". The former is a key-value pair on the Record that a consumer could try find. The latter is the special target field we mentioned previously.

Solving the first problem could be done in a number of ways:

• Write a proc-macro that can unpack the format_args! and determine whether a key-value pair is specified. This wouldn't be possible without a proc-macro because values interpolated into format strings may only be present in the string itself.
• Make upstream changes to format_args! to make additional arguments a warning instead of an error, allow that warning in the format_args! invocation inside the log! macros and always append key-value pairs to the end of the format.
• Discourage complex format strings in favour of more use of key-values.

At this stage, I'd be inclined towards the last point. So instead of writing:

error!("Something happened! {err:?}", err = e);

You would write:

error!(err = e; "Something happened!");

Or possibly:

error!(err = e; "Something happened! {e}");

Solving the second problem could be done by changing the way the target is captured to consider key-value pairs as well:

let target = kvs.get("target").and_then(Value::to_borrowed_str).unwrap_or(module_target);

Using a tt-muncher, we could avoid this work unless we spot a target = key-value pair in the set. We would then deprecate the field-value syntax for target in favour of simply using a target key-value pair.

Taken together, let's consider a complete example that also includes some other pieces of standard context:

error!(target = "my_app", correlation = this_request(), timestamp = now(), error = e; "The request timed out, so couldn't be completed");

In this example, just using key-value pairs in the same way as target, we can scale to supporting any number of special fields, like correlation ids, timestamps, and errors (#357). If a producer did want to include other bits in the format string they can just consider everything after the ; as a kind of string builder:

error!(target = "my_app", correlation = this_request(), timestamp = now(), error = e; "The request timed out, so couldn't be completed {}", e);

---

For what it’s worth, I’ve also got a bit of a squirrel project that reimagines structured logging macros from the start without considering the existing format_args.

[KodrAus]

There's more we can do with these macros, but since we've shipped some key-value support in 0.4.16 I think we can close this one now and use more targeted issues to discuss improvements.