kv macro support

[yoshuawuyts]

Adds key-value support to the log macros. Supersedes #346. Refs #343 #328. Thanks!

Syntax

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",
});

Tasks

• write tests

[KodrAus]

Thanks so much for working on this @yoshuawuyts!

I've just left a comment about how we're capturing values as strings.

[KodrAus]

Ah, we should also be careful not to regress the info!("Hello, {value}", value = 42); case, just based on kv-log-macro it looks like our changes to the macro syntax may not support the ident = expr syntax?

It does also present a bit of a syntactic oddity, where values interpolated into the message would use the ident = expr syntax from format_args, but the captured key-value pairs use the ident: expr syntax like structs:

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

I don't think this is necessarily a problem though, but thought it was worth pointing out.

[yoshuawuyts]

@KodrAus in general it seems we don't have a lot of tests right now -- I was wondering how we might want to go about it?

[KodrAus]

we don't have a lot of tests right now

Yeh, we don't really for the macro syntax, do we. Maybe we could add an integration test file that can do something like this:

struct AssertRecord;

impl Log for AssertRecord {
    fn record(&self, record: &Record) {
        ASSERT.with(|a| a(record));
    }
}

#[test]
fn level_info() {
    // Sets the assert function in thread-local storage
    // then calls the log statement
    test_log!(
        info!("Hello, {value}!", value = "world"),
        |record| {
            assert_eq!("Hello, world!", record.args().to_string();
            assert_eq!(Level::Info, record.level());
        }
    );
}

So that we can build up a suite for the current syntax.

But I'm happy to sketch that out independently if you like? For now I think if we can try find a way to keep ident = expr interpolated values working then we should be good!

[yoshuawuyts]

@KodrAus ohhh, yeah looks like you were onto something there -- I found a bug in my impl which I've fixed, but more importantly the name = val interpolated args aren't indeed no longer working. I've added some basic tests for the macros to prevent this from regressing.

Though I'm not entirely sure how to fix it, so I'm all ears if you have suggestions!

[KodrAus]

Hi @yoshuawuyts!

I'm just circling back to this, I'll spend some time playing with the macros too and see where I end up. We might end up having to tweak the syntax a little (which we could do to consider working more nicely with other extensions like #357).

[yoshuawuyts]

@KodrAus Hi! -- I've been meaning to post an update, but kept putting it off because of reasons, but yea I've spent some time working on this though haven't been able to solve it.

So what seems to be happening is that the macro currently correctly desugars into:

format_args!("hello {cat}", cat = "nori");

But the output isn't working. Why? Well, it turns out that format_args doesn't know what to do with the types, and doesn't further process them but expands them to literally stay as cat="nori", and then tries to match on them:

Now what I suspect is happening here is that cat="nori" is not the right token type, and format_args doesn't know how to process it. This is where I got stuck, because I don't know how to cast the types in macro_rules macros.

I've tried processing it as a tt stream. And also asserted it's indeed an ident (which according to astexplorer.net is the expected type. So well, yeah, that's as far as I got.

Hope this was helpful!

[yoshuawuyts]

@KodrAus did you have any luck getting this to work? If not, perhaps we could ask @dtolnay for help?

[KodrAus]

Hi @yoshuawuyts! 👋

Sorry I’ve been really scattered over the last few months so haven’t been able to make a lot of progress here. However I’m feeling less concerned about regressing this specific edge-case, and I also think implicit inline format args makes the difference between our binding syntax for format args vs kv pairs much less significant.

So all that’s to say I’d be on board with pushing forward with this!

[yoshuawuyts]

@KodrAus yay, that's excellent news! I'm very excited for this!

I just pushed a patch to remove the failing tests, meaning this patch should now be ready to be merged! It seems CI is currently not setup, so it can't verify this patch. But hopefully this is good!

[KodrAus]

It seems CI is currently not setup

Oh dear... Lemme just fix that real quick.

[KodrAus]

@yoshuawuyts would you like to squash and rebase your commits on the current master? I'm thinking the reason actions aren't running here is because we're missing the .github/workflows directory on your branch.

[yoshuawuyts]

@KodrAus rebased and force-pushed. Hoping this works! 🤞

[yoshuawuyts]

Heh, for odd reasons CI is no longer reporting on this branch. My guess is because the repo was migrated it caused some bug in GitHub's UI.

CI link is here: https://github.com/yoshuawuyts/log/runs/295531981 -- it seems cfg_if is failing to build?

[KodrAus]

Ah it looks like cfg-if has removed their explicit MSRV, so I'm trying to get everything back into a good state in #362.

[yoshuawuyts]

Not behind a computer right now but we should try running CI again. Looks like #362 got merged two weeks ago.

[KodrAus]

Yes! Let's merge this in. CI should be good now but if there's any issues I'll get them sorted.

Thanks so much for your patience and effort on this one @yoshuawuyts!

[yoshuawuyts]

@KodrAus Wooot! So happy this got merged! Thank you!

Do you have any idea when this could make it to a release on crates.io? I'm super stoked to start trying it out! ✨

[KodrAus]

@yoshuawuyts Yeh this is an exciting step forward! I'll put together a release PR today and cc you on it. I might get a few other peeps from Libs to take a look at the diff too just to make sure we haven't missed anything.