An RFC for inline expression and value logging

[dekellum]

Add support to log for inline expression and value logging, as a superset of the dbg! macro recently added to rust std.

Rendered

Implementation PR: #316

[KodrAus]

Thanks for putting this together @dekellum! I'll have a proper read shortly, but I've posted a link to the subreddit that points back here, just in case we get any comments there.

[KodrAus]

I quite like how this has turned out 👍

[KodrAus]

Thinking about real-world examples more, I'm guessing these macros would be useful as a way to 'annotate' an expression to trace your way through interesting operations. That suggests we might actually want the expression and format to be reversed in the macro so the most relevant info when scanning the code appears first:

let rem = deadline - Instance::now();

becomes:

let rem = tracev!(deadline - Instance::now(), "{value:?} remaining ({expr})");

where we could interpolate the expression and value as named args into the format.

[dekellum]

I actually had them named in my implementation branch at one point. It's easy to do. As you likely know, you can still use the position references, "{1} {0}" even with named arguments, so I could resurect that in the implementation or you could add it later.

[dekellum]

Also, in my own limited experimentation I like using "{0} -> {:?}" as the format string and I wonder if that would be a better default format, as "->" doesn't appear in any expressions I'm aware of, but = can of course be used for assignment in an expression position.

Edit: In other words by using -> we can avoid more collisions between expression and format.

Thoughts?

[KodrAus]

cc @rust-lang-nursery/libs (apologies for the ping) does anyone have any thoughts on adding dbg!-like macros in the log crate?

As a rough FCP, I'd be on-board with merging and supporting this.

[KodrAus]

Alrighty, let's try a bit of a community final comment period. I'm on board with this feature as proposed. If you'd also like it, please drop a 👍 on this or the original comment. If you have any reservations, please leave a comment here outlining your concerns.

If we haven't registered any concerns by February 15 then I'll merge this one in and we'll ship it in log!

[ssokolow]

I like what I see in the RFC but I want to qualify that with a caution that I've had far too many "Oh, yeah. I never considered that issue." moments while reading through other, more heavily commented-on RFCs.

[dekellum]

So can we merge this and move on to considering the implementation PR? 🙈 🤞

[dtolnay]

Thanks for the ping @KodrAus. Looks like I missed your deadline but my reaction anyway:

I don't think this RFC is sufficiently motivated as written. The std dbg macro, as explained in its documentation that is also quoted in this RFC, is intended for ephemeral debugging use cases. The thing about ephemeral debugging is that being easy to type and untype is valued above almost everything else. It seems to me like this RFC is trying to use easy-to-type as the primary motivation for a use case other than ephemeral debugging, which seems misconceived. If a log line, even at the debug or trace level, is going to exist for longer than one ephemeral debugging session, I think you will find that it is practically always possible and worthwhile to put in an extra 10 seconds of effort to add more context than just the name of a variable or stringify of an expression. At that point I would find it clearer for the log to occur in a statement by itself rather than being dbg-style nested inside a bigger expression or used as a return value.

I have not been involved in API design of the log crate so far so this is just my opinion as an outsider, but I would currently consider myself quite opposed to this change.

One thing that might change my opinion is if @dekellum or anyone else could share a single ironclad real world use case, maybe an extract of ~15 lines of code for context, in which they believe one of these new macros is the best and clearest way to express what the code needs to do. In other words show me the perfect use case for any one of these macros. I don't see that in the RFC text; all the code seems to be toy examples intended to demonstrate syntax only, not intended to justify why the new macros improve on the status quo.

[Centril]

I think you will find that it is practically always possible and worthwhile to put in an extra 10 seconds of effort to add more context than just the name of a variable or stringify of an expression.

If we take an application such as rfcbot there are some places where debug!(..) is used and a custom message is provided. I can only say that from my perspective, having the origin of the logging be printed would have been useful when debugging rfcbot since files + line numbers tend to be more unique and therefore makes it easier to find the relevant places.

Getting the value you gave back is also nice since it doesn't force you to make temporaries just for the purpose of logging.

[dtolnay]

I can only say that from my perspective, having the origin of the logging be printed would have been useful when debugging rfcbot since files + line numbers tend to be more unique and therefore makes it easier to find the relevant places.

File and line number are already present in the log record (https://docs.rs/log/0.4.6/log/struct.Record.html). It sounds like rfcbot will want to configure its logger to include that file and line number in its output.

As far as I can tell from the RFC and the implementation PR, this RFC does not propose doing anything different with file and line information than any of the existing log macros. Without using a logger that emits file and line in the output, rfcbot would continue not having file and line in its log output even if it switches to use logv macros. Sorry if I missed your point -- my interpretation of your response does not seem related to my concerns.

Getting the value you gave back is also nice since it doesn't force you to make temporaries just for the purpose of logging.

This is the easy-to-type argument that I explained I find not at all compelling. To be more explicit, my perspective is that:

// I would never use this because file + line + "n / 2" is not sufficient
// context to make this log line meaningful to me long in the future.
let m = debugv!(n / 2) - 1;

// I would never use this because it would be more clearly expressed with
// the log being its own statement, despite taking more lines.
let m = debugv!("context context {} = {:?}", n / 2) - 1;

[Centril]

File and line number are already present in the log record (https://docs.rs/log/0.4.6/log/struct.Record.html). It sounds like rfcbot will want to configure its logger to include that file and line number in its output.

Oh... right; then my point is wrong... Thanks for the correction!

This is the easy-to-type argument that I explained I find not at all compelling. To be more explicit, my perspective is that:

From my perspective, it's not really about being more easy-to-type but rather about having to invent temporary names for things that aren't semantically significant; temporary let bindings sometimes also require introducing a new block (e.g. compare pat => expr vs. pat => { let tmp = expr; ... }) and so they encourage right-ward drift. Now, I'm not philosophically opposed to let bindings or anything like that... I just think you shouldn't be forced to use them when they are not semantically important. Of course, readability is often quite subjective... :)

[KodrAus]

Looks like I missed your deadline but my reaction anyway

That date was just something I pulled out of thin air to try make things a bit more tangible. I think it's worth working through your feedback first @dtolnay.

This is the easy-to-type argument that I explained I find not at all compelling.

That's a fair point, the main motivation for this is as sugar for capturing the evaluation of some expression. I've been thinking of it as just an alternative way to write log statements that appeals more to some people.

As for not using a raw logv! statement because it doesn't have enough context, I agree, but in ecosystems that support it I find myself avoiding pushing additional context through log statements directly, and relying on some ambient context in a thread-local or something attached to a logger to carry that extra info. That way you don't clutter up the local statement with trivia, and you don't lose that trivia when you're faced with just the formatted log record later.

[KodrAus]

So maybe what we need to do is look at a project like rfcbot and see whether we could really use these new macros to improve its logging?

[dtolnay]

I would like to wait for @dekellum to share a use case that they feel perfectly calls for one of these new macros (and include it in the RFC text). I think that is the crucial missing piece before we can form a meaningful shared opinion on this RFC.

@Centril:

From my perspective, it's not really about being more easy-to-type but rather about having to invent temporary names for things that aren't semantically significant

This doesn't make sense to me because if something is not semantically significant then it shouldn't be in log messages. If something is semantically significant then it is possible to pick a variable name as well as describe in words in the log message what significance the logged value holds.

I think your argument would be easier to articulate and evaluate in the context of a concrete snippet of real world code, which is why I am still pushing for that.

temporary let bindings sometimes also require introducing a new block (e.g. compare pat => expr vs. pat => { let tmp = expr; ... }) and so they encourage right-ward drift.

I acknowledge that rightward drift is a thing. In the absence of a concrete use case, I don't acknowledge that doing more things in the same expression solely to avoid indentation is going to result in the clearest solution.

I think this argument too would be easier to evaluate in the context of a real world code snippet.

@KodrAus:

in languages that support it I find myself avoiding pushing additional context through log statements directly, and relying on some ambient context in a thread-local or something attached to a logger to carry that extra info. That way you don't clutter up the local statement with trivia, and you don't lose that trivia when you're faced with just the formatted log record later.

I used the word context but didn't explain what I mean. I don't mean context as in other values in scope (like what file path we tried to open that failed, or what size of buffer is being used, etc). I mean human language that explains why some value appears in my log. For example this pair of log lines in rfcbot: [1] [2]. Which would you rather see a year after writing the code?

[nag.rs:975] Command is to resolve a concern (actually-a-black-box)
[nag.rs:991] Found a matching concern (actually-a-black-box)

[nag.rs:975] concern_name = "actually-a-black-box"
[nag.rs:991] concern_name = "actually-a-black-box"

You need context to know what is going on with a value that makes it semantically significant (in @Centril's phrasing). Usually this means a verb. In fact every log message in that file uses a verb as context.

So maybe what we need to do is look at a project like rfcbot and see whether we could really use these new macros to improve its logging?

I think the RFC needs to include a snippet of real world code that illustrates one of the macros being used in an ideal way -- where the author believes it to be the best solution. Code from rfcbot would meet my bar for real world code.

[KodrAus]

human language that explains why some value appears in my log

Right, I guess I've been thinking of this with post-structured-logging blinkers, where you'd write:

let command_name = debugv!("Command is to resolve a concern.", get_concern_name());

and get_command_name() and actually-a-block would end up attached as extra data. That snippet wouldn't be useful today, you'd have to include format replacements for the expression and value or you won't see them.

The output of final records not being as useful in the logv macros is a valid concern though that we should have an answer to.

[dtolnay]

I don't see this discussion being productive until someone has proposed a single actual use of any one of these macros. I am unsubscribing for now, but kindly ping me again when anybody has demonstrated a concrete use case that they believe is a good fit -- or go ahead with the RFC if the consensus among others is that hypothetical use cases are sufficient motivation.

I am looking for a single use case that you couldn't write more clearly some other way without the new macros, such as in the case of @KodrAus's last comment which would be more clearly written as:

let concern_name = get_concern_name();
debug!("...", concern_name);

I would insist on the use case being drawn from real world code as opposed to hypothetical or contrived or abstract, and with enough surrounding code to evaluate whether the proposed macros are the most appropriate solution.

[dekellum]

I'm not sure I can offer what you are asking for, or otherwise convince you, @dtolnay. The proposed feature offers a few relatively minor conveniences and is subject, as has been suggested, to style preference. Obviously, every character of log message output can be also be achieved with the existing macros in statement position.

I won't partake in re-litigating the std::dbg! macro addition RFC 2361. Some of your argument for only using the existing logging macros seems to me to be similar to arguments made against that and a prior RFC, e.g. to just use std::eprintln! in all cases. Did you weigh in on that RFC with a consistent opinion? Would @Centril care to comment on that process, history, and summarize the compelling pros/cons given for dbg! vs eprintln!`?

This is my limited, real code experience on the matter:

std::dbg! doesn't work very well with a project that already has log configured, at least in a unit test context, which is very much my preferred context for debugging:

• With cargo test, STDERROR configured log output isn't captured, while dbg! is!?! (At least in my test setup. Apparently that cargo feature does not work at the level of redirecting the process STDERROR file handle? Hooked in at higher level?) In passing tests, unless you are aware of and use the rather elusive and cryptic cargo test -- --nocapture, your dbg! and log output will not both be shown. In failing test runs, the two output sources are printed out of order, not interleaved.

• If you figure out -- --nocapture, you'll notice (see below) that the output formatting is jarringly in two different formats: one configurable by the logging implementation, the other hard-coded by std::dbg! which acts effectively like its own micro-logging system.

• std::dbg! is hard-coded to use "pretty" multi-line format (via {:#?}) which is also jarring by normal logging conventions.

• std::dbg! isn't beholden to log's level or other filtering and thus can't be kept in a project.

• I can turn on thread-name logging in my logging configuration, but not for dbg!

An excerpt of a debugging session with log::trace!, log::debug!, and std::dbg!:

TRACE mio::poll: registering with poller
TRACE tokio_threadpool::builder: build; num-workers=2
TRACE mio::poll: registering with poller
TRACE tokio_threadpool::sender: execute; count=1
TRACE tokio_threadpool::pool:     -> submit external
TRACE tokio_threadpool::pool: signal_work -- notify; idx=1
TRACE tokio_threadpool::pool: signal_work -- spawn; idx=1
[body-image-futio/src/futio_tests/server.rs:73] Tuner::new().set_buffer_size_fs(17).finish() = Tunables {
    max_body_ram: 196608,
    max_body: 1073741824,
    buffer_size_ram: 8192,
    buffer_size_fs: 17,
    size_estimate_deflate: 4,
    size_estimate_gzip: 5,
    size_estimate_brotli: 6,
    temp_dir: "/tmp",
    res_timeout: None,
    body_timeout: Some(
        60s
    )
}
TRACE tokio_threadpool::sender: execute; count=2
TRACE tokio_threadpool::pool:     -> submit external
TRACE tokio_threadpool::pool: signal_work -- notify; idx=0
TRACE tokio_threadpool::pool: signal_work -- spawn; idx=0
TRACE tokio_threadpool::worker: Worker::sleep; worker=WorkerId(1)
TRACE tokio_threadpool::worker:   sleeping -- push to stack; idx=1
TRACE tokio_threadpool::worker:     -> starting to sleep; idx=1

As this real world example shows, it can actually be useful to use verbatim, a rust code expression, stringify-ed directly as the logging context. I just want the same feature as std::dbg!, but directed through a single, configurable, logging system!

My first reaction when I saw the rust RFCs was: dbg! vs debug!, why so important to save 2 characters? Why isn't this hooking into log?

With the std::dbg! djinni out of the bottle, it would now be helpful for log to offer a more direct, but easily discovered super-set.

@dtolnay, in initial comment:

It seems to me like this RFC is trying to use easy-to-type as the primary motivation for a use case other than ephemeral debugging, which seems misconceived.

This exposes a weakness in my terse RFC motivation section, but not the feature. Its perfectly appropriate to add, then shortly remove, uses of the -v macros, or to iteratively replace -v macros with the non-v macro's (only one character to delete) for nicer formatting or context. Its also perfectly appropriate to use the -v macros in statement position, for example:

tracev!(some_long_function_call(x, y, z));
\\-- trace log message: some_long_function_call(x, y, z) = ()

\\ or...
tracev!(some_long_function_call(x, y, z));
\\-- trace log message: some_long_function_call(x, y, z) = "return value lost"

\\ or...
let r = tracev!(some_long_function_call(x, y, z));
\\-- trace log message: some_long_function_call(x, y, z) = "return value bound"

If a log line, even at the debug or trace level, is going to exist for longer than one ephemeral debugging session, I think you will find that it is practically always possible and worthwhile to put in an extra 10 seconds of effort to add more context than just the name of a variable or stringify of an expression.

If your world view is that each log line (Record) should be fully formed, Queen's English sentences with punctuation, then you will most certainly not want to keep use of the -v macros around. Personally I think that might be a goal with info or warn or error level messages, but not so much with debug or trace. The above real world logging excerpt shows TRACE output that is pretty consistent with arbitrary code expressions, as does this excerpt:

TRACE tokio_reactor: loop process - 1 events, 0.000s
TRACE hyper::proto::h1::conn: flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Idle, error: None }
TRACE tokio_threadpool::worker:     -> wakeup; idx=1
TRACE hyper::proto::h1::conn: Conn::read_head
DEBUG hyper::proto::h1::io: read 0 bytes
TRACE hyper::proto::h1::io: parse eof
TRACE hyper::proto::h1::conn: State::close_read()
DEBUG hyper::proto::h1::conn: read eof
TRACE hyper::proto::h1::conn: read_keep_alive; is_mid_message=true
TRACE hyper::proto::h1::conn: flushed({role=server}): State { reading: Closed, writing: Init, keep_alive: Disabled, error: None }

How I intend to use it, and what I think will practically happen, with this feature in place, while developing and debugging code, is:

1. Add tracev!, debugv!, and occasionally, infov! calls as convenient for debugging and demonstrating correct behavior.
2. When getting closer to release grade changes, refine your logging by removing some -v macro calls, and replacing some (but not all) with the existing message formatting macros in statement position, making the messages more of The Queen's English.
3. Check-in (git commit) your code with tracev!, debugv! macro calls in place. If those calls survived to this step, then they are potentially useful in the future to you and other developers, just like the current use of trace and debug.
4. Continue by repeating these steps at (1) and in parallel with other developers doing the same.

(Am I the only one who uses the same process above, with the existing debug! and trace! macros?)

At that point I would find it clearer for the log to occur in a statement by itself rather than being dbg-style nested inside a bigger expression or used as a return value.

Sounds like a general procedural vs functional programming style argument? Some will certainly like to use -v more than others. Still others will just stick with Haskell!

Q: So dbg! was added to rust 1.32 std and the prelude (for real). Why do we have react to that, by adding something similar to log?

A: Because (see above) dbg! doesn't work well once logging is configured, and new users will expect that much parity and consistency! I don't want to have tell someone learning/working with me, not to use dbg!, with no direct replacement in log!

Q: Do the benefits justify the cost of maintaining the feature?

A: (Good question, me.) Outside of this RFC litigation cost, documentation and tests, it costs nearly nothing! Its 65 lines of macro rules code in total, that funnels into the existing log! macro. It might be nice if it integrated with structured logging, if/when that lands, but that's not even a requirement—the answer could be to use the existing (non-v) macro's only, if you want to use structured logging.

You are not going to count the number of public macros and get upset that the '-v' macros doubles them. Why aren't you? Because if that was your concern, you would never have added a macro for each of the 5-logging levels, you would have just stuck with the one log!(Level,…) macro!

So yes, ultimately, I think the convenience benefits for all ecosystem users, justify the costs of adding this to log!

(I'm not so sure my personal costs have been justified at this point, however.)

Conclusion

TL;DR: I'm not misguided. std::dbg! has shortcomings when used with a project that has log configured. The value of the feature does not hinge on the -v macros being long lived in code. The fact that -v macros could be long lived (e.g as debug or trace level) is just a bonus with inclusion in log!.

More seriously, another potential point of compromise on this, to reduce potential future costs more, would be to add the '-v' macros in under a default-on feature flag, with a disclaimer in the rustdoc that the log crate offers no stability guarantees with them and they may become default-off, deprecated, and/or removed in the future—in particular if they are rarely used. (Fuck. I mean, in most other languages, the 0.4.6 crate version number would have already told you that! …I digress. It would be better to cover that in a blog post.) This also would allow log consumer project leads to govern enabling/disabling the feature in there own Cargo.toml.

I'll await your feedback before adding the non-snarky parts of this to the RFC motivation section. Thanks, as always, for your empathy and consideration!

[Centril]

Would @Centril care to comment on that process, history, and summarize the compelling pros/cons given for dbg! vs eprintln!`?

The dbg!(x) macro is meant to be reachable from anywhere (e.g. the playground and in seconds), be maximally easy to write and be unimposing wrt. existing code and typing patterns. The reason why it takes x and then returns it back is so that you can do things like this:

    match 1 {
        x if dbg!(x) == 1 => {},
        _ => {}
    }

fn factorial(n: u32) -> u32 {
    if dbg!(n <= 1) {
        dbg!(1)
    } else {
        dbg!(n * factorial(n - 1))
    }
}

You can get back the original factorial function by simply removing dbg! calls. You don't need to remove any let bindings or such; conversely, to introduce dbg!, it's not necessary to introduce let bindings in a debugging session.

std::dbg! doesn't work very well with a project that already has log configured, at least in a unit test context, which is very much my preferred context for debugging:

Integration with log was a non-goal and I think we never considered unit tests (they are well served by asserts as primary mechanism and dbg!(..) can successfully be used while developing tests).

My first reaction when I saw the rust RFCs was: dbg! vs debug!, why so important to save 2 characters? Why isn't this hooking into log?

Easy... it takes more time to configure log than it takes to type println!(...) so the latter wins almost every time. dbg!(x) has to be more reachable and faster to use than println!(...) and also provide context; it does all of those things. As for debug! vs. dbg! and length, we simply chose the latter because debug! was "already taken".

Sounds like a general procedural vs functional programming style argument?

Haskell has both let x = expr in expr bindings and where clauses. This is more a distinction between pointy and pointfree style. Tho it's more common to find people of the pointfree persuasion in Haskell circles.

---

As for real code, having the features here available, I think I would rewrite:

// we want to panic if we're unable to find any of the usernames
let parsed_teams = teams::SETUP.team_labels().collect::<Vec<_>>();
info!("parsed teams: {:?}", parsed_teams);

as:

// we want to panic if we're unable to find any of the usernames
let parsed_teams = infov!(teams::SETUP.team_labels().collect::<Vec<_>>());

or:

// we want to panic if we're unable to find any of the usernames
let parsed_teams = teams::SETUP.team_labels().collect::<Vec<_>>();
infov!(parsed_teams);

I would rewrite:

        match Pool::builder()
            .max_size(CONFIG.db_pool_size)
            .build(manager)
        {
            Ok(p) => {
                info!("DB connection pool established.");
                p
            },
            Err(why) => {
                error!("Failed to establish DB connection pool: {}", why);
                panic!("Error creating connection pool.");
            }
        }

as:

        match Pool::builder()
            .max_size(CONFIG.db_pool_size)
            .build(manager)
        {
            Ok(p) => infov!(p, "DB connection pool established, {:?}."),
            Err(why) => {
                error!("Failed to establish DB connection pool: {}", why);
                panic!("Error creating connection pool.");
            }
        }

[dekellum]

@Centril:

we simply chose the latter [dbg!] because debug! was "already taken".

And for that in particular, and for all the other details you are providing, I am forever in your debt!

[dekellum]

@Centril, to continue this 💓fest (or risk a horrible breakup) this works too:

    panic!(errorv!("fatal attraction💓!"));

DEFINATELY NOT in this RFC or its implementation PR, but separately, I foresee the creation of the ellusive (...drum role...) fatal! macro. Another one, yah!

[KodrAus]

In this latest round of examples, we've been a bit fast-and-loose with whether or not the expression and value are actually interpolated into the format. Using the format_args! macro we wouldn't be able to do that (unless std was changed to emit a warning instead of an error for unused arguments that you could ignore). It seems like a bit of a papercut to have to include them if you don't want to. Without relying on a proc macro, we could take a message independently of the format and put them together ourselves:

match Pool::builder()
            .max_size(CONFIG.db_pool_size)
            .build(manager)
        {
            Ok(p) => infov!(p, "DB connection pool established."),
            Err(why) => panic!(errorv!(why, "Failed to establish DB connection pool")),
        }

where infov!(p, "DB connection pool established.") expands to something like:

format_args!("{msg} ({fmt})", msg = "DB connection pool established", fmt = format_args!("{expr} -> {value:?}", expr = "p", value = p));

with an optional extra argument for the expression format:

infov!(p, "DB connection pool established.", "`{expr}` produced `{value:?}`");

If you just call infov!(p) then you'd just get the {expr} -> {value:?}.

[dekellum]

Interesting idea.

In my last half joking case, that's why I suggested/threatened to propose a new fatal! macro, which could handle the gap in my composed example: panic!(errorv!("msg")) which, as you may have noticed, with current impl. will produce ("msg" = "msg") as the log message, before panic'ing, which is well short of perfect.

If there was a way to make that just work, that would certainly be a plus.

Edit: Well there is a hackish way, using zero width format specifier. In fatal!, that detail would be conveniently hidden.

Having waited a while for this here, I don't think we should wait for a format_args_lenient! macro to stabilize in rust core that is lenient about missing placeholders in the format string, but if that ever happened, it would be backward compatible to start using it, wouldn't it?

In your proposed alternative, since both prefix and format are optional, wouldn't we need a marker token like '=', ';', "prefix:", "format:" or the like to distinguish them? But If the normal case doesn't need it, it might not be too bad.. There is already the precedence of the "target:" marker.

[KodrAus]

In your proposed alternative, since both prefix and format are optional, wouldn't we need a marker token like '=', ';', "prefix:", "format:" or the like to distinguish them?

I would suggest we simply require a textual message be given if you also want to override the format for the expression and value.

[dekellum]

But format_args_lenient! would solve it and avoid needing two parameters, wouldn't it? It wouldn't be backward compatible to go back from two parameters to one, though. Edit: Or more importantly, I reread it again, and I still don't understand what you are driving at and what is gained by the split into two parameters?

[KodrAus]

Hmm, I wouldn't rely on a format_args_lenient! becoming a thing in the standard library that we could plug into, and as an external proc macro I think we could go back from two parameters without breaking existing users of one parameter.

Having separate parameters for a message and format at least gives us some clear indication that there's a separate magic part of the format that uses format arguments you aren't explicitly providing.

[dekellum]

Also, just to use a trick I just learned from @Centril, this works as intended:

    let panic_msg = format!("fatal attraction {}!", "💓");
    panic!(errorv!(panic_msg));

Edit: But just to be clear, below is probably the better code for this case (well at least, before there is a fatal! macro)!

    let panic_msg = format!("fatal attraction {}!", "💓");
    error!("{}", panic_msg);
    panic!(panic_msg);

Edit 2: Added the dumb "{}" pattern, to get it to compile, so sad.

[KodrAus]

@dekellum splitting the message into text and a format lets you write:

infov(p, "A message. We don't need to include any format args");

and guarantee that it will work on the compiler version that log currently targets and produce something like:

INFO: A message. We don't need to include any format args (p = 42)

It reduces the barriers to associating a useful message with a logv call, which is important for longterm usefulness. Requiring a message before you can alter the value format assumes that customising the format of the value itself (display, debug, multiline etc) is of secondary importance to annotating the expression and value that gets logged.

[dekellum]

OK, now I understand your position. I'd like to think about that more, but looks like it at least deserves a place in the alternatives of the RFC.

[dekellum]

Note, also in the RFC, the order of parameters is currently reversed. To change that I would like to hear a detailed justification. My justification for current order is that it is consistent with the existing message logging (non-v) macros.

[KodrAus]

My reasoning for reversing the order is that when scanning the code visually it keeps the actual expression on the left where it's closer to the assignment:

let x = infov!(1 / 2, "noise noise noise noise noise noise noise noise noise noise noise noise");

vs:

let x = infov!("noise noise noise noise noise noise noise noise noise noise noise noise", 1 / 2);

I don't necessarily think inconsistency with ordering for the message logging macros is a big deal here. For the message logging macros, the message itself is the significant part of the statement, so coming before args makes sense. For expression logging macros, the expression itself is the significant part of the statement.