Since 2.2.2, named format arguments are broken

[agalakhov]

Hi,

since the version 2.2.2 the following code: error!(logger, "at {name:?}: {sym:#}", name = frame.ip(), sym = demangle(name))); stopped working with an error "slog::Value is not satisfied", while error!(logger, "at {:?}: {:#}", frame.ip(), demangle(name))); still works properly.

Here "demangle" is the one from rustc_demangle crate returning a struct of type Demangle, and ip() returns *c_void.

Regards, Alexey

[dpc]

Is it only 2.2.2, or other 2.2.x are also affected?

[agalakhov]

2.2.1 is not affected, the issue was first discovered while updating from 2.2.1 to 2.2.2.

[dpc]

Must have been #165 since it was the only change between these versions. I'll look into it later, maybe today.

[dpc]

@Techcable Any ideas?

[Techcable]

Whew, this took me down quite the rabbit hole!

I've created a simple regression test and managed to reproduce the issue not only on 2.2.2 but also on 2.2.1 and 2.2.0.

It appears that the problem is that a formatting argument to the log macro is interpreted also interpreted as . In other words, on the 2.2.x series error!(logger, "at {name:?}: {sym:#}", name = frame.ip(), sym = demangle(name))) is actually interpreted as error!(logger, "at {name:?}: {sym:#}", name = frame.ip(), sym = demangle(name)); "name" => frame.ip(), "sym" => demangle(name)). Interpreting these as structured arguments creates a clear problem because neither *const c_void nor Demangle implements slog::Value. As a temporary workaround, I suggest that you resort to locking a dependency against version 2.1.1 :(

Interestingly enough the issue does not arise at all on the 2.1.0 series, which at first glance appears to give the correct macro trace output and passes all the tests. Although I did fail out of my macro wizard school, it appears to me that @dpc 's named format changes are the real cause of this issue :( @agalakhov Are you sure you didn't misread 2.1.1 as 2.2.1?

[dpc]

Oh dear. I don't have time today. Will try tomorrow. Thanks for analysis @Techcable

[agalakhov]

I'm sure I did not misread, but now I'm not sure that it really compiled with exactly 2.2.1. Most likely yes since the problem was first discovered on Jenkins after automatic upgrade which does not skip versions, and for one day it worked.

Thank you! I just changed the code so that arguments are not named anymore.

[dpc]

So named argument changes in 2.2.0 broke it. I'm really so for that, since it's technically a breaking change, but I don't want to change it. Basically named arguments have to be slog::Values now, since they will be added to the logging statement as a normal key-value pair. This allows compacting everything and reusing same values both in the message for humans and key-value list for robots.

[dpc]

I would be happy to include a PR where Value is implemented for types like c_void to help with it. In future, once rust has default impl we could have Value implemented by default for anything that has Display that would also make it work.

[agalakhov]

I expect named arguments to work exactly like the unnamed ones. Just giving a variable a name should not change any semantics, am I wrong? Value should be required either for none or for both named and unnamed ones.

[dpc]

No, you're not wrong. Everything works like that for types that implement both slog::Value and Display. In your case, so happens, that you have two types that don't.

But I don't believe I can implement this very useful feature (having named arguments added to KVs) in any way that would break the symmetry here. I would have to go with some procedural macros that parse strings etc. Or I need default impl in the stable Rust, which is going to happen eventually, I belive.

[agalakhov]

I understand that it works so but I don't expect such a behavior. If I call println!, I'm free to write arguments with or without name, as I like. I expect that all other macros with format!-like syntax also have format!-like semantics. Having one with some special semantics is a very bad surprise for daily coding.

[Techcable]

As a workaround, we could add a nightly-only feature that has a default impl when T is Debug or Display.

[dpc]

@Techcable That seems like a good idea.

[dpc]

I acknowledge the problem, but I won't fix it, sorry. No resources.

[daniel-abramov]

@dpc could we let the issue be opened, so that when some other developers encounter a problem, they at least know that such problem exists and do not open a new issue for that. And maybe someone else will work on fixing the issue when he/she has time.

As far as I understood the problem described by @agalakhov it basically affects the logging behavior, i.e. when the one writes one thing without named arguments, it works fine, whereas when the same thing (with the same types) is written as a string with format arguments, it stops working (although it should), so there seems to be a logical bug which has to be fixed eventually, otherwise we have an inconsistent behavior which is not anticipated by the user of the library.