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]

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]

Thanks for working through this @dekellum!

adding the message prefix parameter obviates the need to specify the entire format, and the library can own the expression part of the format, also making value format customization easier to use, when it is needed.

Ah that's an interesting point. In the larger Rust codebases I've worked on I've always ended up defining my own logging macros anyways, so it doesn't seem unreasonable to want to do this.

Having to specify at least a blank ("") message prefix in order to customize the value format is a minor nuisance.

It is a bit of a nuisance, but spun another way it's an encouragement to improve the utility of your log macros by adding a message. If I saw an empty string in a logging expression in a code review I'd probably be a little suspicious.

I primarily wanted to mention the size increases in case some other roving commentator shows up next month, to say this is too complicated, and shouldn't be added!

That's fair! The log macros are already a bit obtuse, but I think that's just how macros end up, so am not too worried about that.

Personally, over the long term I can see us completely rebuilding the macros in log at some point, either internally or by shifting them out into a separate crate, but it makes sense to try offer the best end-user experience with the tools we have today. We'll have to live with them for a long time in any case. Both approaches have pros and cons, but in my opinion the split message/format doesn't surface its cons in the happy-path. Still, I'm interested to hear what other folks think about that.

[dekellum]

I've updated the RFC to include some additional motivation, and for the design change for the two customization parameters.

[dekellum]

Regarding the design question of -v macro parameter ordering:

The macro's can be made to work with either order, so I believe this is purely a question of clarity of design, including least-surprise, as well as long term ease of use. My position remains to stay with the existing design and RFC (before and as recently updated). Here is a more detailed justification:

(1) If you consider the optional target, which is first in every public log macro, the proposed reversed ordering has required parameters sandwiched between optional parameters on both sides, e.g:

debugv!([target: "target",] <expression>, ["prefix",] ["value-format"])

This would make explaining the parameters that much harder. Or would you prefer, for this alternative, to also move the parameter target to the right? (And if so, where exactly?)

Whereas, the current RFC design has the only required parameter on the far right:

debugv!([target: "target",] ["prefix",] ["value-format",] <expression>)

(2) Compared with the existing message formatting macros, parameters:

debug!([target: "target",] "format string literal", [<expression>,] [...])

As previously noted, the current -v macro design is more consistent with the existing message formatting macros. This extends to logv! consistency with log!. Beyond just perceived consistency, as per the Expected Usage mentioned here and since added to the RFC: converting from -v macros to non-v formatting macros, and also in the other direction, is expected. The rust code edit distance is minimized with the current argument order. For example, starting from:

debugv!("refine", some_result);

…and converting to:

debug!("refine some result: {:?}", some_result);

or vice versa.

(3) The current argument order matches the output order of the message:

debugv!("prefix in code and in output", logged_at_end());

(4) Your prior example, @KodrAus, is at least 101 characters long, so rustfmt would yield:

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

Which doesn't obscure the expression. Also, I suspect that in common usage the prefix context will be much shorter given that the expression is also logged. If it really needs to be this long, it probably makes sense to factor out the logging into a info! macro on its own line, see (2). Note that, IMO, its quite common to split out separate statements, adding let bindings, etc. as needed, to avoid long lines (that rustfmt might otherwise butcher).

(5) I'm not aware of any existing precedence in Rust for the proposed alternative ordering, i.e. a parameter that will be returned, should be first? I wouldn't be surprised if some other language does have some precedence for some order, but it may or may not be relevant to Rust.

[KodrAus]

Hmm, I think we're risking becoming a bit of an echo-chamber on the ordering question. The parameter ordering is starting to seem like the kind of design decision we'd be better off determining through actual usage, right now it's a bit arbitrary and we could justify it in either direction. So based on that I'd be happy to stick with the order you've already specified, but reserve the right to change it based on user feedback before 'stabilization'.

Which brings up the question of how we'd like to roll this out. We don't really have a history of unstable features in log, but I think for logv, we could start by providing them through an opt-in unstable feature-gate, with the expectation that someone in a project like rustc, cargo, rfcbot or something else will spike out using these macros to see how effective they are and in turn potentially tweaking the macros in breaking ways based on that experience. Once they're actually seeing use then we could stabilize them by removing the unstable feature gate.

Any thoughts on that?

[dtolnay]

I have re-read the RFC. This is much improved from the original draft -- nicely done. The proposed design has improved and the motivation has been fleshed out.

Still I don't think this feature should be accepted. I understand that it is something many people would like to use, and I see that it makes certain code easier to type, and it results in output that is prettier than mixing log+dbg, but I don't think the cost–benefit is where it would need to be for this change to be a net positive on the experience of logging in Rust.

Mastery

Mainly I am concerned that we are adding decisions and knowledge where there didn't used to be decisions and knowledge required. I see a lot of value for new and experienced log users alike from never having to pause and think whether code would be "cleaner" if we logged a warning the other way of logging a warning. I never want there to be a debate on a code review, or even a single comment asking the (probably less experienced) author to please do it the other way. I don't want people to try to articulate elaborate "best practices" for when to logv in expression position, when to logv in statement position, when to normal log that all just boil down to personal preference. I don't want people to stumble on logv performing a move of its arguments when as a beginner we all had to learn as a special case that println (and by extension, log) do not move arguments despite writing no & on them like for function calls.

In my view the entire experience of there now being more to learn, more steps before attaining complete mastery of the crate, and more things to think when writing code, make the feature not worth its benefits. I like that the log crate today is easy to master. I find it freeing -- because when you want to log, for the most part you just do it and it's clear how.

Analogy

My position may sound weird because if people want to use a thing and it makes code easier to write and maybe read, is an obvious generalization of existing log and std APIs, and all the other benefits, then of course we should accept it. I think over time I have come to wish for more restraint in the design process than that.

I will point out one past design question where I think restraint came up in a way that shares a lot of similarities with this one -- the issue of #{expr} interpolation in the quote crate, dtolnay/quote#88. I don't want for this to be a big distraction, but I bring it up because I think it will help convey the shape of my opinion on logv by analogy with something that the others on this thread don't already have an invested opinion on, so may find it easier to recognize the point of view.

See the thread, but basically the quote crate supports interpolation of single variables with #var and various people over time have proposed interpolating expressions with #{expr} to support e.g. extern #{f.abi} fn #{f.name}. This was:

• proposed independently by multiple users;
• an obvious extension of existing functionality;
• trivial to implement (4 lines);
• negligible increase in the surface area of the crate;
• easy to learn / remember / understand / teach;
• makes code easier to write, sometimes much easier;
• makes certain code easier to read;
• supported by Alex, one of the most frequent and most experienced users of the crate;

that is to say almost every good thing that you could say about a feature, and everything that we traditionally look for when evaluating and accepting features. And yet when I considered the aggregate experience of using the crate, and everything that entails, I felt that the feature would lead to a worse experience for users. In other words it makes the crate worse.

I have a very similar feeling on this RFC. I think it is good for so many reasons, and yet altogether it is a bad thing for this crate.

Counterproposal

We keep using the existing log macros, we use dbg for ephemeral debugging, we live with the differences in formatting between them, and we fix env_logger (rust-cli/env_logger#127) to behave well under the test harness.

[dekellum]

Yeah I didn't think I'd convince you of anything, @dtolnay!

I do appreciate your intuition, but I think it embeds a certain logical fallacy regarding the current state of the ecosystem, circa rust 1.32.

• Existing log users, as easy to "master" as I agree it is, are not going to have much new to take in with the -v macros, which they can slowly experiment with and adopt, or not, as they may choose.

• The new users that might struggle with the extra choice of -v vs non-v macros, or understanding the move semantics of -v, are now starting to use std::dbg!, likely before even reaching for log. BTW std::dbg! seems to be quite well received. When and if they do reach for log 0.4.6, they are going to be disappointed with the log + std::dbg experience and lack of a log equivalent for std::dbg!. If instead the -v macros are available, they would be able to take their std::dbg! learnings and simply re-apply them, more productively with log.

Said another way, your position on this would be much more compelling, to me at least, if dbg! hadn't, quite miraculously given its own obstacles, already made it into rust std.

Finally, the log + std::dbg experience can't be well fixed with changes to env_logger, since it neither the only logger, nor in control of the problems. Hopes for making test output capture reliable, has been subsumed into a complete Test Framework Overhaul, rust-lang/rust#50297, and my guess from reading, is that is a bit far off. When and if that is in place, and at best, we still would be stuck with std::dbg!'s hard-coded format and lack of other features.

I want to make it clear, I'm not bashing std::dbg! here. I think its a good feature, and it makes some sense to do it the way they did it, like a micro-logging system. I (and I think others) just want parity in a single log API and system.

[dekellum]

If you are following along… I was finally able to use some of my open source time budget for using debugv in a real setting. In this case its improve the logging directly in tests, and I intend to keep these debugv uses in place once merged. Some notes:

• Removes 46 lines, adds 27 lines of test code (includes whitespace, YMMV).
• I didn't feel the need to use either of the debugv customization parameters in any of these cases.
• In some cases, I made a variable name more human friendly for use as the expression in the log. That neither seems like cheating nor a bad thing to promote, actually.
• I found debugv composed nicely with try-? and Option or Result::unwrap() chaining, as commonly used in these tests. For example:

    let record = debugv!(reader.read(&tune))?.unwrap();

This BarcReader::read can return None on end-of-file, so inserting debugv in that position gracefully logs that case, before it would panic on unwrap, and where the remainder of the test works with Some(Record). Yes, I know I could have also used expect("not to read None") or similar, but this also logs the happy path and keeps things compact.

Otherwise the changes are pretty boring, actually, which I think is a useful thing to demonstrate with a feature such as this, and the recent suggestion that it could be a distraction, or something worse. There is no currying, or other forms of leftist propaganda in these changes! In this setting, its much more of a 1-to-1 mapping of the intended use for std::dbg!, but better integrated and for keeping around. See the diff. below:

dekellum/body-image@dev...debugv-in-tests-0

[KodrAus]

My starting point for this RFC was Rust is an expression-oriented language, so it seems reasonable to offer expression-oriented log macros. In that context, having an equivalent set of logv macros makes sense, but as @dtolnay has pointed out, that also comes with problems. Creating decisions where there were none before and inviting valueless discussion are problems when I think logging is something that is most effective when it's free of ceremony and roadblocks to adoption. Anything that's not clear is a roadblock, and is likely to result in things not being logged.

If we're going to continue down this path then I think we could alleviate some of the possible confusion around whether you should be using log or logv by only offering the debugv macro (like @dekellum's original PR). That way the decision process is: use debugv instead of dbg if it's available, and use debugv instead of debug if you're tracing your way through an expression and it's convenient. You should associate a contextual message with your debugv calls.

[Centril]

If the sole purpose of the new macro is for debugging, then one possibility to consider is that log may expose log::dbg!(..) which take the exact same inputs as std::dbg!(..) (moving the inputs, move semantics, requiring Debug, etc.) and returns the same output.

If use log::dbg occurs and the macro is in scope, then log's methodology for logging happens, otherwise the macro is chosen from the prelude. This eases the transition between std and log such that you don't really have to care which one you are using and so that you can switch at a moments notice.

However, one important aspect of this is that log should commit to only using the input and output forms that the standard library provides. If the log crate moves outside of this, this may set expectations for the standard library, negate smooth transitioning, or be just confusing.

[dekellum]

Related to the feature gate sub-thread, which I still owe you a response to @KodrAus, we could separate debugv!and tracev! as feature logv and the remaining -v macro levels as feature logv_extra (thinking out loud on feature names). The point being that project leads get to opt in to what extent they would like to have these in their own codebase.

@Centril, I would prefer to not, by default, shadow your std::dbg! name, but thank you for offering it! Of course individual consumer projects could still decide to alias debugv! as dbg! if that is their preference. They could also make that a fixed one-argument macro, or accept our additional current 0-3 customization parameters, which IMO are nice if not always used addition in a log context.

[dtolnay]

I like the idea to add just log::dbg with the same input patterns as std::dbg. I would expect an RFC with justification explaining the advantages over simply using std::dbg for that use case (given that dbg use cases tend to be about getting the job done, not about beauty of output, so differences in the formatting of the filename/line between log output and dbg output doesn't seem so detrimental). But the idea seems like a promising direction to me!

[dekellum]

@KodrAus wrote:

My starting point for this RFC was Rust is an expression-oriented language, so it seems reasonable to offer expression-oriented log macros. In that context, having an equivalent set of logv macros makes sense,

I've consistently agreed with that, and believe the current RFC is a good expression of, and design for, that goal. Yes tracev! and debugv! happen to fill an important and immediate gap in relation to std::dbg! and testing, but I also took @Centril's proposed use cases for infov!, etc. seriously. Should I not have, @Centril? I know you are perfectly capable of writing your own infov!-like macro if you want one, but I had treated your use cases as being indicative of how other users would start using the -v feature in log.

as @dtolnay has pointed out, that also comes with problems. Creating decisions where there were none before and inviting valueless discussion

See my response above, but TL;DR: overblown. Could be applied to anything new in the logging space, like for example, Structured Logging.

Just to be clear at this point, I'm not going to write a new alternative RFC that dumbs this down to a single log::dbg macro, that:

1. Purposefully makes the log API subordinate to current and future libstd decisions regarding std::dbg!. This could later make necessary, non-PATCH safe changes and release of log, for example, if @Centril manages to re-introduce the multi-value input, tuple-output support in dbg! in some later rust release. Or, @Centril, is your motivation different? Really any future change to std::dbg! could require some complicated rust-version aware dance in log. Have you all really thought this through?

2. Introduce a log::dbg! with no continuity with the rest of the log API. Presumably a log::dbg! could not even include an optional target: parameter, and would need to be hard-coded for pretty-print multi-line output despite that not being a log norm. And for this purpose, you would also have me just pretend that the log::tracev! level didn't exist?

@dtolnay, can you explain how you are somehow more comfortable with this log::dbg!alternative? Is it just that the imposed discontinuity avoids violating your envisaged sanctity of the existing log output macros?

I tried to offer several points of comprise, but honestly even the whole feature gate, non-stable concept is over extending. The -v feature is purely macro-rules, and users that don't want these macros don't have to import them. How much of this conservatism ("more restraint") just stems from this uniquely-rust-inflicted SemVer cul-de-sac that the the log crate finds itself in? Specifically, the need to release a new shim "0.4.7" (which is non-PATCH safe from a SemVer perspective) just to make a "0.5" point release?

[dtolnay]

@dekellum:

See my response above, but TL;DR: Overblown. Could be applied to anything new in the logging space, like for example, Structured Logging.

Selecting features where the argument cannot be applied is not the point. The goal is selecting features whose benefits outweigh their costs. Despite an argument being applicable to a feature, it is possible for that feature to be worthwhile because it brings greater benefits.

How much of this conservatism ("more restraint") just stems from this uniquely-rust-inflicted Semver cul-de-sac that the the log crate finds itself in? Specifically, the need to release a new shim "0.4.7" (which is non-PATCH safe from a Semver perspective) just to make a "0.5" point release?

None, I think. I'm not sure how that would have anything to do with it. My view continues to be that the RFC would be a net bad thing for this crate. I would hold the same opinion if we were designing the crate from scratch with no versioning considerations.

Similar to how I think the benefits of #{expr} do not outweigh the costs to include in a quote crate, even a brand new one. Similar to how the benefits of ++ increment operators do not outweigh the cost of including them in Rust.

All of these things would have undeniable benefits if added. All of them are things that people would happily use. Any of these, if it gets added, would have people excitedly thinking "finally! I have been waiting to use that". People would use them and love them because they only see the benefits; these features are easy to want. It is much harder in general for people to perceive drawbacks of things like any of these three (logv, #{expr}, ++) because it requires them to think (and have experience thinking) about the entire experience of a feature, rather than individual instances of using it.

++ in particular is strikingly similar to this RFC. Both of them boil down to, why would you do in two lines what you could do in one line and save indentation? That's looking at the benefit, but does not take into account the drawbacks.

  match op {
-     Op::Write(byte) => {
-         outbuf[pos] = byte;
-         pos += 1;
-     }
+     Op::Write(byte) => outbuf[pos++] = byte,

[dekellum]

@dtolnay: I do hesitate to drag Structured Logging in for example purposes, my apologize @KodrAus , but then again, it at least has to do with logging! If I understand @KodrAus correctly on that feature, he is going to just release a new set of logging macro's in another crate that are structured logging friendly, for example, preserving the message template and named argument as structure. So this just moves the problem up beyond log, as a decision for new users and new projects as to what logging API they are going to use. Ode to those proverbial good old days, when it was easy to just use log, positioned as the one true rust logging API. Now people are going to need to debate the merits of different APIs in different crates.

Looks like tokio-trace might be including std::dbg! parity, but I'm not sure how general purpose a logging API that actually is? I can't decide which to use!

https://github.com/tokio-rs/tokio-trace-nursery/blob/ad5e1eb4de578bc0223a402c455d005da3b44ca3/tokio-trace-macros/src/lib.rs#L5

With your position @dtolnay, are we effectively relegating log to a much smaller role as keeper of a Logger static atomic (e.g. set_logger) for a legacy logging system?

[dtolnay]

I don't see it playing out that way, no. If it does play out that way, it won't be for lack of logv macros.

[dtolnay]

On a re-reading of the thread, I noticed that you conflate the position of being against these new macros as
"conservatism" -- #317 (comment). That may be me not having explained well enough how I meant "restraint". Let me try again so that I maybe alleviate your worry of becoming a legacy logging system in #317 (comment).

Conservatism is opposition to change or innovation. What I meant by restraint is different: critically evaluating tradeoffs. The example of ++ differentiates them. Including ++ in Rust would have been conservative because every other similar language has it. Critically evaluating the benefits and drawbacks and deciding not to include ++ was restraint but quite opposite to conservatism. Maybe "diligence" would be better word choice.

Accepting features is not a requirement for staying a successful and relevant library long-term. Evaluating tradeoffs is a requirement.

[dekellum]

@dtolnay: Many trade-offs were evaluated in just taking this design and RFC to its current point. You needn't lecture further on that as a concept. Unfortunately, I think you and I are just going to have to agree to disagree on our respective risk vs. benefit analysis of the current RFC.

I'm still perplexed and missing an important facet of your position, regarding the above mentioned log::dbg!, how it is different from the RFC, and might somehow be acceptable to you—but I fear exploring that might be a further waist of both our time, so I won't ask again.

Sincerely, I thank you for your time and consideration.

[dekellum]

More -v macro usage in a realistic setting: dekellum/body-image@0708dba7a

The -v form composes well with futures 0.1 and its typical method chaining, here with some usage of the optional message prefix. Still just in test code, but of course a well tested project will have a lot of test code.

[KodrAus]

@Centril:

If the sole purpose of the new macro is for debugging, then one possibility to consider is that log may expose log::dbg!(..) which take the exact same inputs as std::dbg!(..) (moving the inputs, move semantics, requiring Debug, etc.) and returns the same output.

That's an interesting idea that sounds promising to me too 🤔 If we did something like that it would probably be instead of something like debugv though so it might be worth exploring a little here. It seems like a fair alternative that's easy to motivate and has a clear single usecase, but I can think of a few tradeoffs to consider too:

• Being tied to the same API as std::dbg creates a risk that changes or improvements to std::dbg that we can't replicate here in log means it's no longer a true drop-in replacement for std::dbg. That could be a non-issue if we try to be log-aware when discussing changes that affect std::dbg.
• Not having a contextual message with the expression means log::dbg would be as ephemeral as std::dbg, but by virtue of living in log it could be interpreted as a non-quick-and-dirty alternative to std::dbg.

@dekellum:

See my response above, but TL;DR: overblown.

Hmm, I wouldn't quite go that far. Creating confusion by offering a parallel and not obviously more applicable API is a concern that's tricky to measure and a bit speculative, but it's a valid one nonetheless.

release a new set of logging macro's in another crate that are structured logging friendly ... So this just moves the problem up beyond log, as a decision for new users and new projects as to what logging API they are going to use.

The goal of that work is a little different. It's a point-in-time effort to unblock the benefits for the growing list of structured frameworks to integrate with log without blocking on a feature that needs a lot more design work. It should eventually find its way back into log, or we'll restructure log. It's not really important just yet.

I tried to offer several points of comprise, but honestly even the whole feature gate, non-stable concept is over extending.

I have to disagree with this point. It does seem unnecessary if we think of this API purely in terms of its immediate impact on a codebase that imports log, but is important to give us a chance to see how they play out in practice before committing to that exact API proper. The feature-gate would be a tool for the maintainers of log to have some wiggle room, rather than a tool for consumers of log to ignore APIs they're not interested in. The point about restraint is wider than just log, but we do have some unique constraints that make breaking changes costly.

we could separate debugv!and tracev! as feature logv and the remaining -v macro levels as feature logv_extra (thinking out loud on feature names).

That sounds like a fair starting point to me, but I would put either just tracev or debugv behind one gate and the rest behind another. That way we could get some idea of who's interested in the full set of expression-oriented macros vs just the std::dbg equivalent.

---

Also, I realise we've never explicitly stated what our expectations on RFCs are here in log, so it's possible we're all on different pages with respect to what accepting this means. That's my bad. I haven't been considering these RFCs as a kind of binding contract to ship exactly what they outline. I've been considering them as a focal point for discussion about new features in log, and as a future historical artifact that captures that discussion that we can come back to. In that discussion/documentation context, we'll want to give ourselves a chance to change/add/remove things before actually committing to supporting the feature over the long term, even if that ends up looking a little differently to what's described in the RFC.

[dekellum]

So I think the current RFC is a well reasoned and complete design for the expression and value logging feature as conceived. Thanks for all your input helping to make the RFC and design better!

This seems now stalled, perhaps awaiting more compelling input, on the existential question: Will users be confused by having the choice of using this?

(TL;DR: Ultimately I think that prospective users are smarter than that, and will be well prepared by use of std::dbg!.)

To obtain more feedback, as well as to get on with things, I've gone ahead and implemented your earliest advice, @KodrAus, by publishing the work as the standalone tao-log crate. Editing a project's Cargo.toml to add tao-log as a dependency (possibly replacing the log dep.) may be about as much work as setting additional non-default log features, were they available.

This is released under the same license as log and I've made it clear that this is derivative work of this RFC process and the original PR #316 under log. I still believe it would be better to include this in log proper, and I am willing to offer some time to do that, if this RFC is eventually approved.

Of course I would also appreciate any feedback you might have on tao-log and its documentation, here or via the dekellum/tao-log repo. For example, its currently unclear if my changes for a new overview of log output macros would be well received here in log, or how that might need to change for non-default feature gates.

[pravic]

What is holding us from approving this RFC?

[dtolnay]

@pravic I am still strongly opposed to accepting this into the crate. See my writeups above, which still reflect my current opinion.

The only new information relative to the 2019 discussion is that the proposed macros have been available on crates.io for >2 years (#317 (comment)) and so far nobody outside the RFC author has found it worth using that crate.

Probably if that crate were to become somewhat widely used then we could reevaluate here.

[KodrAus]

It's been a while since we've visited this. It doesn't look like something we'll accept in log itself at this stage, but the work is still valid and has been good to explore. Thanks for all the effort in putting this together!

I'll go ahead and close this one now to keep our open set of things closer to what's actively on our plates.

[WalterSmuts]

Probably if that crate were to become somewhat widely used then we could reevaluate here

@dtolnay Given that I specifically wanted this feature for the past year and gave a couple of attempts at trying to find it, I don't think this is a valid way to judge if folks are looking for this feature.

and so far nobody outside the RFC author has found it worth using that crate.

That sounds a bit catty... Also wrong... Given that it's got 7K downloads