An RFC for inline expression and value logging #317
No reviewers
Labels
No labels
bug
duplicate
easy
enhancement
help wanted
invalid
question
rfc
structured-logging
wontfix
No milestone
No assignees
1 participant
Notifications
Due date
No due date set.
Dependencies
No dependencies set
Reference
gh-rust-lang/log!317
Loading…
Reference in a new issue
No description provided.
Delete branch "rfc-v-macros"
Deleting a branch is permanent. Although the deleted branch may continue to exist for a short time before it actually gets removed, it CANNOT be undone in most cases. Continue?
Add support to
logfor inline expression and value logging, as a superset of thedbg!macro recently added to ruststd.Rendered
Implementation PR: #316
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.
@ -0,0 +1,325 @@# SummaryI quite like how this has turned out 👍
@ -0,0 +286,4 @@convenience, the design was changed to use two separate optionalcustomization parameters, for the prefix and value format.## Release this as a separate crate, not in `log`This is the big question for me. Are users of the
logcrate going to get enough value out oflogvto warrant building and supporting a parallel API?Your point about
debug,info,warnetc already being effectively parallel APIs is reasonable though.@ -0,0 +305,4 @@partially mitigated by documented such an extension crate in the logREADME and/or top-level library rustdoc.* The community effort to maintain such a separate library withOn the other hand, supporting this in
logbecomes a similar burden for folks working onlogitself, but the expected parity betweenlogandlogvstyle macros when they're both inlogbecomes even tighter.@ -0,0 +308,4 @@* The community effort to maintain such a separate library withcompatibility to the `log` crate, as it evolves. For example, the_-v_ macros will likely need to be adapted, when structured loggingis implemented ([log RFC 296]).How this interacts with structured logging will be interesting. I think we should be able to decorate a
Recordwith at least the stringified expression as a structured value, and use theDebugrepresentation of the value if the user hasn't supplied an explicit format function tologv.@ -0,0 +1,325 @@# SummaryI don't think this is borne out;
dbg!(a, b, c)is desired:And moreover I don't think it was the reason 2173 was closed:
The main issue was instead that the original macro permitted labels, took into account debug/release mode and environment variables.
If all you want to do is extend the
dbg!macro to support multiple arguments that's quite exceedingly simple (playground):As you can see, to support multiple arguments a single line was required, and one for supporting
dbg!().What the original macro did wrt. multiple arguments, and which contributed significantly to complexity, was to lock stderr only once so as to improve performance, but that might not actually be important so the code above works if we are more concerned about complexity than performance.
Why do I bring all this up? Well... I have a bit of a concern that if
loggoes for a format string rather than multiple arguments (which I think is more useful fordbg!'s quick debugging purpose), then it will be somewhat expected thatdbg!also does this as opposed to adding multi argument support. My concern is lessened by the fact that you're not calling the macrodbg!, but I would like to be disabused of this concern entirely such that the standard library is free to go in either direction.@ -0,0 +1,325 @@# SummaryThanks @Centril. I will refine this alternative subsection to (a) presume less about why RFC 2173 was superseded; (b) point out that both multiple arguments and a custom format string are at least somewhat at odds, and (c) note that the following still works, as currently designed, by explicitly passing a tuple:
Regarding your multiple argument example macro: It would be surprising and undesirable in a log context, I think, to write more than one log record for a single -v macro invocation. To "lock stderr only once" sounds like a closely related goal.
@ -0,0 +308,4 @@* The community effort to maintain such a separate library withcompatibility to the `log` crate, as it evolves. For example, the_-v_ macros will likely need to be adapted, when structured loggingis implemented ([log RFC 296]).This is, in addition to allowing the same sort of structured key+values, at the end of the -v macro arguments? Here I think you are providing evidence in favor of including this feature in log itself, so these features can be more closely integrated as appropriate.
@ -0,0 +1,325 @@# SummaryThanks @dekellum; I agree with you about the distinction between logging and debugging wrt. the usefulness of multiple arguments;
dbg!(a, b, c)seems more useful thandebugv!(a, b, c). Fwiw, I think this RFC is a nice addition. :)@ -0,0 +305,4 @@partially mitigated by documented such an extension crate in the logREADME and/or top-level library rustdoc.* The community effort to maintain such a separate library withThat's entirely fair, but note also that the implementation of
logv!is currently pretty minimal and ultimately funnels intolog!. The other -v macros (debugv!, etc.) are one line rules.@ -0,0 +1,325 @@# SummaryUpdated this alternatives subsection, per above, and with further elaboration.
@ -0,0 +308,4 @@* The community effort to maintain such a separate library withcompatibility to the `log` crate, as it evolves. For example, the_-v_ macros will likely need to be adapted, when structured loggingis implemented ([log RFC 296]).Yeh, I was running through the exercise of whether we'd be worse off for adding this feature and then having to introduce structured logging without breakage to it later, which I think we'll be able to do just fine. So no issues there.
@ -0,0 +305,4 @@partially mitigated by documented such an extension crate in the logREADME and/or top-level library rustdoc.* The community effort to maintain such a separate library withI think the issue is more tied to the amount of context than to the amount of code to support. It just means it's another feature to keep in mind when evolving the library.
I find your argument about the duplicated macros we already have for
info,warnetc pretty convincing though. It's not like we don't already have a suite of similar macros.cc @rust-lang-nursery/libs (apologies for the ping) does anyone have any thoughts on adding
dbg!-like macros in thelogcrate?As a rough FCP, I'd be on-board with merging and supporting this.
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!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.
So can we merge this and move on to considering the implementation PR? 🙈 🤞
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.
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.
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.
This is the easy-to-type argument that I explained I find not at all compelling. To be more explicit, my perspective is that:
Oh... right; then my point is wrong... Thanks for the correction!
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
letbindings sometimes also require introducing a new block (e.g. comparepat => exprvs.pat => { let tmp = expr; ... }) and so they encourage right-ward drift. Now, I'm not philosophically opposed toletbindings 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... :)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.
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.So maybe what we need to do is look at a project like
rfcbotand see whether we could really use these new macros to improve its logging?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:
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.
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:
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?
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.
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.
Right, I guess I've been thinking of this with post-structured-logging blinkers, where you'd write:
and
get_command_name()andactually-a-blockwould 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
logvmacros is a valid concern though that we should have an answer to.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:
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.
@ -0,0 +1,325 @@# SummaryThinking 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:
becomes:
where we could interpolate the expression and value as named args into the format.
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 usestd::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 fordbg! vseprintln!`?This is my limited, real code experience on the matter:
std::dbg!doesn't work very well with a project that already haslogconfigured, 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, whiledbg!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 crypticcargo test -- --nocapture, yourdbg!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 bystd::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!, andstd::dbg!: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 asstd::dbg!, but directed through a single, configurable, logging system!My first reaction when I saw the rust RFCs was:
dbg!vsdebug!, why so important to save 2 characters? Why isn't this hooking intolog?With the
std::dbg!djinni out of the bottle, it would now be helpful forlogto offer a more direct, but easily discovered super-set.@dtolnay, in initial comment:
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
-vmacros, or to iteratively replace-vmacros with the non-v macro's (only one character to delete) for nicer formatting or context. Its also perfectly appropriate to use the-vmacros in statement position, for example: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-vmacros around. Personally I think that might be a goal withinfoorwarnorerrorlevel messages, but not so much withdebugortrace. The above real world logging excerpt shows TRACE output that is pretty consistent with arbitrary code expressions, as does this excerpt:How I intend to use it, and what I think will practically happen, with this feature in place, while developing and debugging code, is:
tracev!,debugv!, and occasionally,infov!calls as convenient for debugging and demonstrating correct behavior.git commit) your code withtracev!,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 oftraceanddebug.(Am I the only one who uses the same process above, with the existing
debug!andtrace!macros?)Sounds like a general procedural vs functional programming style argument? Some will certainly like to use
-vmore than others. Still others will just stick with Haskell!Q: So
dbg!was added to rust 1.32stdand 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 usedbg!, with no direct replacement inlog!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 haslogconfigured. 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
logcrate 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 allowlogconsumer 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!
@ -0,0 +308,4 @@* The community effort to maintain such a separate library withcompatibility to the `log` crate, as it evolves. For example, the_-v_ macros will likely need to be adapted, when structured loggingis implemented ([log RFC 296]).Agreed. I touch on this a little in my below response to @dtolnay, going to resolve these here.
@ -0,0 +1,325 @@# SummaryI 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.@ -0,0 +1,325 @@# SummaryAlso, 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?
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 takesxand then returns it back is so that you can do things like this:You can get back the original
factorialfunction by simply removingdbg!calls. You don't need to remove any let bindings or such; conversely, to introducedbg!, it's not necessary to introduce let bindings in a debugging session.Integration with
logwas a non-goal and I think we never considered unit tests (they are well served by asserts as primary mechanism anddbg!(..)can successfully be used while developing tests).Easy... it takes more time to configure
logthan it takes to typeprintln!(...)so the latter wins almost every time.dbg!(x)has to be more reachable and faster to use thanprintln!(...)and also provide context; it does all of those things. As fordebug!vs.dbg!and length, we simply chose the latter becausedebug!was "already taken".Haskell has both
let x = expr in exprbindings andwhereclauses. 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:
as:
or:
I would rewrite:
as:
@Centril:
And for that in particular, and for all the other details you are providing, I am forever in your debt!
@Centril, to continue this 💓fest (or risk a horrible breakup) this works too:
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!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:where
infov!(p, "DB connection pool established.")expands to something like:with an optional extra argument for the expression format:
If you just call
infov!(p)then you'd just get the{expr} -> {value:?}.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.
I would suggest we simply require a textual message be given if you also want to override the format for the expression and value.
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?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.
Also, just to use a trick I just learned from @Centril, this works as intended:
Edit: But just to be clear, below is probably the better code for this case (well at least, before there is a
fatal!macro)!Edit 2: Added the dumb "{}" pattern, to get it to compile, so sad.
@dekellum splitting the message into text and a format lets you write:
and guarantee that it will work on the compiler version that
logcurrently targets and produce something like:It reduces the barriers to associating a useful message with a
logvcall, 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.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.
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.
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:
vs:
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.
I'd like to address the latest suggested -v macro interface changes in an incremental fashion, here, starting with the idea to split the customization parameters into a message prefix parameter and format parameter. The suggestion to change the parameter order is mostly orthogonal, so I will address that subsequently.
I agree that a contextual message prefix is going to be more common than changing the format. I also like this change, because it makes it possible to do as per an existing RFC alternative: Only customize the value part of the format. In other words, 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.
This change does come at the cost of some complexity. It was 64 lines of macro rules. This adds another 22. Also in working through documentation (to make sure it was easily explainable), I added another 7 lines of documentation. See an excerpt of this below:
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!
Having to specify at least a blank (
"") message prefix in order to customize the value format is a minor nuisance.Also it adds the possibility of some other mis-usage, one without a compiler error, and some other possible strange compiler errors:
So I see pros and cons. If we stayed with the existing RFC, '-v' macro interface for now, this could be revisited later/elsewhere, with a procedural macro that checked for 0 or 2 format placeholders in the single argument custom format argument. If it has 0 placeholders then we treat it like just the message prefix. If it has 2 then it is used as the entire format. If it has any other number, issue a sane compiler error. A procedural macro could also presumably make all of the above cases have sane compiler errors, with the 2-argument design, but we'd have to live with these quirks in the interim.
Thoughts on this design consideration?
Thanks for working through this @dekellum!
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.
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.
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
logat 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.I've updated the RFC to include some additional motivation, and for the design change for the two customization parameters.
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
logmacro, the proposed reversed ordering has required parameters sandwiched between optional parameters on both sides, e.g: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:
(2) Compared with the existing message formatting macros, parameters:
As previously noted, the current -v macro design is more consistent with the existing message formatting macros. This extends to
logv!consistency withlog!. 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:…and converting to:
or vice versa.
(3) The current argument order matches the output order of the message:
(4) Your prior example, @KodrAus, is at least 101 characters long, so rustfmt would yield:
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.
@ -0,0 +1,325 @@# SummaryNaming format args is no longer relevant (current RFC) given that only the value format is customizable. Parameter order under consideration below.
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 forlogv, we could start by providing them through an opt-in unstable feature-gate, with the expectation that someone in a project likerustc,cargo,rfcbotor 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?
@ -0,0 +1,325 @@# SummaryI would like to understand this better before using it as motivation. How is it that a logger configured to stderr or stdout circumvents the test harness's capture of stderr and stdout? Is that a bug that needs to be fixed, eliminating the motivation?
There is value in successful tests remaining quiet.
@ -0,0 +1,325 @@# SummaryThis might be specifically directed at
env_logger, which usestermcolorto write to the terminal by default.termcolorin turn doesn't use theprint!oreprint!macros so it doesn't hook into some special unstable APIs those macros andlibtestuse to figure out if output should be captured. We're working around it inenv_loggerat the moment, but I'd call this a point-in-time issue.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, https://github.com/dtolnay/quote/pull/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
#varand various people over time have proposed interpolating expressions with#{expr}to support e.g.extern #{f.abi} fn #{f.name}. This was: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 (https://github.com/sebasmagri/env_logger/pull/127) to behave well under the test harness.
@ -0,0 +1,325 @@# SummaryMy observations are with the
fernlogger implementation, which I chose for its features with a CLI binary, and then figured would be best to stick with for test logging. It ultimately useswrite!(std::io::Stderr,…)I believe. So it seems that the test harness isn't actually capturing stderr/out at the process level. Perhaps it can't without also abandoning test threads in a single process? It seems pretty fragile. Will it even work whendbg!oreprintln!are found in lib code, outside of#[cfg(test)]?@ -0,0 +1,325 @@# SummaryDigging around a bit more, I found this summary of the capture weakness of libtest pretty helpful:
https://github.com/rust-lang/rust/issues/50297#issuecomment-388988381
It suggests it is also vulnerable when other threads beyond the test thread log.
Edit: And I can confirm that libtest indeed fails to capture
dbg/e/println!in other threads, as is the case with some client/server testing in the same place I used in my log output demo.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
logusers, 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 forlog. BTWstd::dbg!seems to be quite well received. When and if they do reach forlog0.4.6, they are going to be disappointed with thelog+std::dbgexperience and lack of alogequivalent forstd::dbg!. If instead the -v macros are available, they would be able to take theirstd::dbg!learnings and simply re-apply them, more productively withlog.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 ruststd.Finally, the
log+std::dbgexperience can't be well fixed with changes toenv_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 withstd::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 singlelogAPI and system.If you are following along… I was finally able to use some of my open source time budget for using
debugvin a real setting. In this case its improve the logging directly in tests, and I intend to keep thesedebugvuses in place once merged. Some notes:debugvcustomization parameters in any of these cases.debugvcomposed nicely with try-?andOptionorResult::unwrap()chaining, as commonly used in these tests. For example:This
BarcReader::readcan returnNoneon end-of-file, so insertingdebugvin that position gracefully logs that case, before it would panic on unwrap, and where the remainder of the test works withSome(Record). Yes, I know I could have also usedexpect("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:https://github.com/dekellum/body-image/compare/dev...debugv-in-tests-0
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
logvmacros 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
logorlogvby only offering thedebugvmacro (like @dekellum's original PR). That way the decision process is: usedebugvinstead ofdbgif it's available, and usedebugvinstead ofdebugif you're tracing your way through an expression and it's convenient. You should associate a contextual message with yourdebugvcalls.If the sole purpose of the new macro is for debugging, then one possibility to consider is that
logmay exposelog::dbg!(..)which take the exact same inputs asstd::dbg!(..)(moving the inputs, move semantics, requiringDebug, etc.) and returns the same output.If
use log::dbgoccurs and the macro is in scope, thenlog'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
logshould commit to only using the input and output forms that the standard library provides. If thelogcrate moves outside of this, this may set expectations for the standard library, negate smooth transitioning, or be just confusing.Related to the feature gate sub-thread, which I still owe you a response to @KodrAus, we could separate
debugv!andtracev!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 aliasdebugv!asdbg!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.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!
@KodrAus wrote:
I've consistently agreed with that, and believe the current RFC is a good expression of, and design for, that goal. Yes
tracev!anddebugv!happen to fill an important and immediate gap in relation tostd::dbg!and testing, but I also took @Centril's proposed use cases forinfov!, etc. seriously. Should I not have, @Centril? I know you are perfectly capable of writing your owninfov!-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 inlog.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::dbgmacro, that:Purposefully makes the
logAPI subordinate to current and future libstd decisions regardingstd::dbg!. This could later make necessary, non-PATCH safe changes and release oflog, for example, if @Centril manages to re-introduce the multi-value input, tuple-output support indbg!in some later rust release. Or, @Centril, is your motivation different? Really any future change tostd::dbg!could require some complicated rust-version aware dance inlog. Have you all really thought this through?Introduce a
log::dbg!with no continuity with the rest of thelogAPI. Presumably alog::dbg!could not even include an optionaltarget:parameter, and would need to be hard-coded for pretty-print multi-line output despite that not being alognorm. And for this purpose, you would also have me just pretend that thelog::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 existinglogoutput 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
logcrate 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?@dekellum:
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.
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.@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 uselog, 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!github.com/tokio-rs/tokio-trace-nursery@ad5e1eb4de/tokio-trace-macros/src/lib.rs (L5)With your position @dtolnay, are we effectively relegating
logto a much smaller role as keeper of aLoggerstatic atomic (e.g.set_logger) for a legacy logging system?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.
On a re-reading of the thread, I noticed that you conflate the position of being against these new macros as
"conservatism" -- https://github.com/rust-lang-nursery/log/pull/317#issuecomment-468768068. 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 https://github.com/rust-lang-nursery/log/pull/317#issuecomment-468818537.
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.
@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.
@ -0,0 +1,325 @@# SummaryRefined this motivation section in the RFC to link to the same and better describe the issue, and its awkward workarounds.
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.
@Centril:
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
debugvthough 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:std::dbgcreates a risk that changes or improvements tostd::dbgthat we can't replicate here inlogmeans it's no longer a true drop-in replacement forstd::dbg. That could be a non-issue if we try to belog-aware when discussing changes that affectstd::dbg.log::dbgwould be as ephemeral asstd::dbg, but by virtue of living inlogit could be interpreted as a non-quick-and-dirty alternative tostd::dbg.@dekellum:
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.
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
logwithout blocking on a feature that needs a lot more design work. It should eventually find its way back intolog, or we'll restructurelog. It's not really important just yet.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 oflogto have some wiggle room, rather than a tool for consumers oflogto ignore APIs they're not interested in. The point about restraint is wider than justlog, but we do have some unique constraints that make breaking changes costly.That sounds like a fair starting point to me, but I would put either just
tracevordebugvbehind 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 thestd::dbgequivalent.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 inlog, 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.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-logas a dependency (possibly replacing thelogdep.) may be about as much work as setting additional non-defaultlogfeatures, were they available.This is released under the same license as
logand I've made it clear that this is derivative work of this RFC process and the original PR #316 underlog. I still believe it would be better to include this inlogproper, 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.What is holding us from approving this RFC?
@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 (https://github.com/rust-lang/log/pull/317#issuecomment-469855550) 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.
It's been a while since we've visited this. It doesn't look like something we'll accept in
logitself 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.
@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.
That sounds a bit catty... Also wrong... Given that it's got 7K downloads
Pull request closed