From 63e6ce0b13111bc19308834fd07a86a952842542 Mon Sep 17 00:00:00 2001 From: David Kellum Date: Wed, 30 Jan 2019 11:52:26 -0800 Subject: [PATCH 1/9] RFC inline-expression-value-logging --- rfcs/0001-inline-expression-value-logging.md | 191 +++++++++++++++++++ 1 file changed, 191 insertions(+) create mode 100644 rfcs/0001-inline-expression-value-logging.md diff --git a/rfcs/0001-inline-expression-value-logging.md b/rfcs/0001-inline-expression-value-logging.md new file mode 100644 index 000000000..27eeb9364 --- /dev/null +++ b/rfcs/0001-inline-expression-value-logging.md @@ -0,0 +1,191 @@ +# Summary + +Add support to `log` for inline expression and value logging, as a +superset of the `dbg!` macro recently added to rust `std`. + +# Motivation + +The motivation is in part the same as for the accepted `dbg!` macro of +[RFC 2361] and implemented in rust 1.32. To summarize: + +* Its convenient to be able to insert logging into larger expressions + without needing to restructure using additional `let` bindings, or + by duplicating sub-expressions. + +* For debug/trace level logging in particular, automatic formatting of + the expression with its value can give sufficient context in the log + (particularly with _target_, _file_ and _line_ information) and avoids + additional boilerplate. + +In a project where configuring `log` and an output logger +implementation hasn't (yet) happened, one can conveniently use +[`std::dbg!`](https://doc.rust-lang.org/std/macro.dbg.html), with no +initial setup cost, for `expression = value` printing to STDERR. From +the linked rustdoc: + +> Note that the macro is intended as a debugging tool and therefore +> you should avoid having uses of it in version control for longer +> periods. Use cases involving debug output that should be added to +> version control may be better served by macros such as `debug!` from +> the `log` crate. + +Indeed, a major point of the `log` package and `Level`s, is the +ability to keep `debug!` and `trace!` logging in place for further +use, including by other contributors, without paying a cost for +unlogged messages in release builds. + +It follows that for projects that _do already have_ `log` and an +output logger dependency and configuration, and particularly with some +debug/trace logging already in place, use of `std::dbg!` would be +unwelcome in PRs, and likely less productive than a `log`-based +equivalent. For parity of convenience, the `log` API needs an +extension for logging expressions and passing through values inline. + +# Detailed Design + +In addition to the existing set of _formatted logging_ macros, by +level, e.g. `trace!`, `debug!`, etc., we add a new set of _inline +expression and value logging_ macros, with a “_-v_” suffix: `tracev!`, +`debugv!`, and so forth for all levels. The _-v_ macros take a _single_ +expression argument, which is evaluated exactly once, regardless of if +the logging level is enabled or not, and returned: + +```rust +let n = 12; +let m = debugv!(n / 2) - 1; +// ^-- debug log message: "n / 2 = 6" +assert_eq!(m, 5); +``` + +The _default_ format string for the _-v_ macros is `"{} = {:?}"`, +where the `stringify!`-ed expression and resulting value are passed, +in that order. Note that the `std::dbg!` macro currently uses `"{} = +{:#?}"`—the value is "pretty-printed", potentially over multiple +lines. Given the line-orientation of logging output, the default +format for the _-v_ macros avoids this. However, a custom format may +also be passed before the expression, which adds considerably more +output flexibility: + +```rust +let i = 32; +tracev!("{} = {}", i); // use `Display` instead of `Debug` +tracev!("{} = {:x}", i); // hexadecimal format value +tracev!("{} = {:#?}", i); // use pretty, multi-line format + +let rem = infov!("{1:?} remaining ({0})", deadline - Instance::now()); + // value first, with additional context +``` + +For symmetry with the existing `log!` macro, a `logv!` is also +included, which allows passing a `Level` as parameter. + +Finally, like all the other public logging macros, the _-v_ macros +allows overriding the default module-path target with a string +literal: + +```rust +let i = 33; +let j = warnv!(target: "maths", (i-1) / 2); +assert_eq!(j, 16); +``` + +See also the [implementation PR], which includes guide level +documentation, in the form of rustdoc with doc-tests. + +# Alternatives + +## Multiple expression support + +[RFC 2173] included multiple-expression support for `std::dbg!` but +was closed, at least in part due to perceived complexity with multiple +expressions and tuple value returns, in preference to [RFC 2361] which +was ultimately merged and implemented. While `log` is arguably a "more +advanced" tool, the complexity of multiple expression support does not +seem to be warranted by the functional gain or convenience win, over +using the existing formatted logging macros for more complex +formatting requirements. + +## DSL extension of existing log macros + +Instead of adding a new set of _-v_ macros, it would be possible to +extend the existing logging macros by using some additional marker +syntax, such as the following: + +```rust +debug!(= n/2) +trace!("{} = {:x}", =i); +``` + +Here the `=` signals that the expression should be `stringify!`-ed for +the message and its value returned from the macro. This complicates +the macro's, but more importantly, considerably complicates the +necessary guide documentation for new and existing users to understand +an evolving logging _DSL_ as new syntax. This syntax isn't any more +compact. It aids comprehension when the macro arguments are as +function-like as possible, by introducing the _-v_ macros specific to +the feature as designed. + +## Only customize the value part of the format + +As proposed above, the entire format string may be customized. Until +understanding that the single `i` argument is expanded to two +arguments for formatting, it is surprising to see the following, as +used above, with two placeholders in the format string: + +``` rust +tracev!("{} = {:x}", i); +``` + +A workable alternative would be to only allow customizing the value +part of the format, and have the expression part be fixed as `"{} = +"`: + +``` rust +tracev!("{:x}". i); +``` + +While this alternative is more compact for the subset of compatible +use cases, it offers _less_ customization options. For example, +supplying a custom literal prefix to the message, for additional +context. It is also less symmetric with the the _formatted logging_ +macros, where the format string literal represents the _entire_ text +message of the log `Record`. Finally, this alternatives adds a small +but measurable amount of formatting overhead, as the value needs to be +formatted to a temporary `fmt::Arguments` before formatting to the +final message. + +## Release this as a separate crate, not in `log` + +The proposed additional logging macros play the same role as, for +example, the existing `debug!` macro in `log`, which is just more +convenient than using `log!(Level::Debug, …)` with an extra import. + +Ease of use was also an important part of the design and decision to +add `dbg!` to rust `std` and the prelude. + +While the proposed additions would still require import for the +macro(s), at least in 2018 edition projects, adding this feature to +`log` avoids: + +* Needing to _discover_, add, and maintain an additional library + dependency. Discovery may be the biggest issue, and the inclusion of + `dbg!` in `std` and the prelude raises a high bar. This could be + partially mitigated by documented such an extension crate in the log + README and/or top-level library rustdoc. + +* The community effort to maintain such a separate library with + compatibility to the `log` crate, as it evolves. Fro example, _-v_ + macros will likely need to be adapted, for example, when structured + logging is implemented ([log RFC 296]). + +The [implementation PR] (as of this writing) adds just 74 lines +non-test code, only of `macro_rules!`. + +# Unresolved Questions + +None. + +[RFC 2173]: https://github.com/rust-lang/rfcs/pull/2173 +[RFC 2361]: https://github.com/rust-lang/rfcs/pull/2361 +[log RFC 296]: https://github.com/rust-lang-nursery/log/pull/296 +[implementation PR]: https://github.com/rust-lang-nursery/log/pull/316 From 262405a2eb5dc08e256fda402b4918f57704ee30 Mon Sep 17 00:00:00 2001 From: David Kellum Date: Wed, 30 Jan 2019 13:39:53 -0800 Subject: [PATCH 2/9] fix typos --- rfcs/0001-inline-expression-value-logging.md | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/rfcs/0001-inline-expression-value-logging.md b/rfcs/0001-inline-expression-value-logging.md index 27eeb9364..4449bb8c2 100644 --- a/rfcs/0001-inline-expression-value-logging.md +++ b/rfcs/0001-inline-expression-value-logging.md @@ -149,7 +149,7 @@ use cases, it offers _less_ customization options. For example, supplying a custom literal prefix to the message, for additional context. It is also less symmetric with the the _formatted logging_ macros, where the format string literal represents the _entire_ text -message of the log `Record`. Finally, this alternatives adds a small +message of the log `Record`. Finally, this alternative adds a small but measurable amount of formatting overhead, as the value needs to be formatted to a temporary `fmt::Arguments` before formatting to the final message. @@ -174,12 +174,12 @@ macro(s), at least in 2018 edition projects, adding this feature to README and/or top-level library rustdoc. * The community effort to maintain such a separate library with - compatibility to the `log` crate, as it evolves. Fro example, _-v_ - macros will likely need to be adapted, for example, when structured - logging is implemented ([log RFC 296]). + compatibility to the `log` crate, as it evolves. For example, the + _-v_ macros will likely need to be adapted, when structured logging + is implemented ([log RFC 296]). The [implementation PR] (as of this writing) adds just 74 lines -non-test code, only of `macro_rules!`. +of non-test code, all of which is `macro_rules!`. # Unresolved Questions From 372c6d831b22835db5ca262a37470da4537675e3 Mon Sep 17 00:00:00 2001 From: David Kellum Date: Thu, 31 Jan 2019 13:00:12 -0800 Subject: [PATCH 3/9] rfc: code count previously included blank lines --- rfcs/0001-inline-expression-value-logging.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/rfcs/0001-inline-expression-value-logging.md b/rfcs/0001-inline-expression-value-logging.md index 4449bb8c2..5636181bf 100644 --- a/rfcs/0001-inline-expression-value-logging.md +++ b/rfcs/0001-inline-expression-value-logging.md @@ -178,7 +178,7 @@ macro(s), at least in 2018 edition projects, adding this feature to _-v_ macros will likely need to be adapted, when structured logging is implemented ([log RFC 296]). -The [implementation PR] (as of this writing) adds just 74 lines +The [implementation PR] (as of this writing) adds just 65 lines of non-test code, all of which is `macro_rules!`. # Unresolved Questions From bc9ddce5839af221c4bbc7b849485a437be74a49 Mon Sep 17 00:00:00 2001 From: David Kellum Date: Thu, 31 Jan 2019 13:02:33 -0800 Subject: [PATCH 4/9] Improve analysis of alternate, multi-expression support --- rfcs/0001-inline-expression-value-logging.md | 41 ++++++++++++++++---- 1 file changed, 33 insertions(+), 8 deletions(-) diff --git a/rfcs/0001-inline-expression-value-logging.md b/rfcs/0001-inline-expression-value-logging.md index 5636181bf..b3f5e5ecf 100644 --- a/rfcs/0001-inline-expression-value-logging.md +++ b/rfcs/0001-inline-expression-value-logging.md @@ -96,14 +96,38 @@ documentation, in the form of rustdoc with doc-tests. ## Multiple expression support -[RFC 2173] included multiple-expression support for `std::dbg!` but -was closed, at least in part due to perceived complexity with multiple -expressions and tuple value returns, in preference to [RFC 2361] which -was ultimately merged and implemented. While `log` is arguably a "more -advanced" tool, the complexity of multiple expression support does not -seem to be warranted by the functional gain or convenience win, over -using the existing formatted logging macros for more complex -formatting requirements. +[RFC 2173] included multiple expression printing and return of values +via tuple for `std::dbg!`, but was closed in preference to [RFC 2361] as +merged and implemented. RFC 2361 on this particular [design +aspect][2361-single]: + +> If the macro accepts more than one expression (returning a tuple), +> there is a question of what to do with a single +> expression. Returning a one-value tuple `($expr,)` is probably +> unexpected, but _not_ doing so creates a discontinuity in the macro's +> behavior as things are added. With only one expression accepted, +> users can still pass a tuple expression or call the macro multiple +> times. + +In relation to the proposed design of this RFC, accepting multiple +expressions would also be at odds with allowing an optional custom +format string as a preceding parameter. To support both would require +an additional marker, e.g. `debugv!(format: "{} = {:x}", i, j)`, as +further complication and bulk. + +As suggested in RFC 2361, explicitly passing a multiple expression +tuple works when desired, and avoids complications to both the +syntax and macro implementation: + +```rust +let j = 19; +let (q, r) = debugv!((j/4, j%4)); +\\ ^-- debug log message: (j / 4, j % 4) = (4, 3) +let (q, r) = debugv!("quarter {} = {:?}", (j/4, j%4)); +\\ ^-- debug log message: quarter (j / 4, j % 4) = (4, 3) +assert_eq!(q, 4); +assert_eq!(r, 3); +``` ## DSL extension of existing log macros @@ -189,3 +213,4 @@ None. [RFC 2361]: https://github.com/rust-lang/rfcs/pull/2361 [log RFC 296]: https://github.com/rust-lang-nursery/log/pull/296 [implementation PR]: https://github.com/rust-lang-nursery/log/pull/316 +[2361-single]: https://github.com/rust-lang/rfcs/blob/master/text/2361-dbg-macro.md#accepting-a-single-expression-instead-of-many From 907343ab270afeda6ef17aa6d5c11f16496ac32a Mon Sep 17 00:00:00 2001 From: David Kellum Date: Fri, 1 Feb 2019 09:34:51 -0800 Subject: [PATCH 5/9] rfc: fix more typos, minor improvements --- rfcs/0001-inline-expression-value-logging.md | 21 ++++++++++---------- 1 file changed, 10 insertions(+), 11 deletions(-) diff --git a/rfcs/0001-inline-expression-value-logging.md b/rfcs/0001-inline-expression-value-logging.md index b3f5e5ecf..b3041206e 100644 --- a/rfcs/0001-inline-expression-value-logging.md +++ b/rfcs/0001-inline-expression-value-logging.md @@ -6,9 +6,9 @@ superset of the `dbg!` macro recently added to rust `std`. # Motivation The motivation is in part the same as for the accepted `dbg!` macro of -[RFC 2361] and implemented in rust 1.32. To summarize: +[RFC 2361], as implemented in rust 1.32. To summarize: -* Its convenient to be able to insert logging into larger expressions +* It is convenient to be able to insert logging into larger expressions without needing to restructure using additional `let` bindings, or by duplicating sub-expressions. @@ -77,7 +77,7 @@ let rem = infov!("{1:?} remaining ({0})", deadline - Instance::now()); ``` For symmetry with the existing `log!` macro, a `logv!` is also -included, which allows passing a `Level` as parameter. +included, which allows passing the `Level` as a parameter. Finally, like all the other public logging macros, the _-v_ macros allows overriding the default module-path target with a string @@ -145,9 +145,9 @@ the message and its value returned from the macro. This complicates the macro's, but more importantly, considerably complicates the necessary guide documentation for new and existing users to understand an evolving logging _DSL_ as new syntax. This syntax isn't any more -compact. It aids comprehension when the macro arguments are as -function-like as possible, by introducing the _-v_ macros specific to -the feature as designed. +compact. Comprehension is aided when the macro arguments are as +function-like as possible, with macros specific to the feature, as +designed above. ## Only customize the value part of the format @@ -161,16 +161,15 @@ tracev!("{} = {:x}", i); ``` A workable alternative would be to only allow customizing the value -part of the format, and have the expression part be fixed as `"{} = -"`: +part of the format, and with the expression part fixed as `"{} ="`: ``` rust -tracev!("{:x}". i); +tracev!("{:x}", i); ``` While this alternative is more compact for the subset of compatible -use cases, it offers _less_ customization options. For example, -supplying a custom literal prefix to the message, for additional +use cases, it offers less customization options. For example, it does +not support adding a custom literal prefix to the message, for additional context. It is also less symmetric with the the _formatted logging_ macros, where the format string literal represents the _entire_ text message of the log `Record`. Finally, this alternative adds a small From 9654c069c9c56cd4d70d50cb9c2e3dfacd8b61ac Mon Sep 17 00:00:00 2001 From: David Kellum Date: Fri, 1 Feb 2019 09:54:04 -0800 Subject: [PATCH 6/9] rfc: actually, no overhead of value only format --- rfcs/0001-inline-expression-value-logging.md | 5 +---- 1 file changed, 1 insertion(+), 4 deletions(-) diff --git a/rfcs/0001-inline-expression-value-logging.md b/rfcs/0001-inline-expression-value-logging.md index b3041206e..0da6695f6 100644 --- a/rfcs/0001-inline-expression-value-logging.md +++ b/rfcs/0001-inline-expression-value-logging.md @@ -172,10 +172,7 @@ use cases, it offers less customization options. For example, it does not support adding a custom literal prefix to the message, for additional context. It is also less symmetric with the the _formatted logging_ macros, where the format string literal represents the _entire_ text -message of the log `Record`. Finally, this alternative adds a small -but measurable amount of formatting overhead, as the value needs to be -formatted to a temporary `fmt::Arguments` before formatting to the -final message. +message of the log `Record`. ## Release this as a separate crate, not in `log` From 3371ae34ac6e1b92df33dc8cccd122668e06c1cb Mon Sep 17 00:00:00 2001 From: David Kellum Date: Sat, 2 Feb 2019 06:37:56 -0800 Subject: [PATCH 7/9] rfc: typo --- rfcs/0001-inline-expression-value-logging.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/rfcs/0001-inline-expression-value-logging.md b/rfcs/0001-inline-expression-value-logging.md index 0da6695f6..aa4390f33 100644 --- a/rfcs/0001-inline-expression-value-logging.md +++ b/rfcs/0001-inline-expression-value-logging.md @@ -170,7 +170,7 @@ tracev!("{:x}", i); While this alternative is more compact for the subset of compatible use cases, it offers less customization options. For example, it does not support adding a custom literal prefix to the message, for additional -context. It is also less symmetric with the the _formatted logging_ +context. It is also less symmetric with the _formatted logging_ macros, where the format string literal represents the _entire_ text message of the log `Record`. From 3392019c398f0a7b36e83fcf09175f361828799d Mon Sep 17 00:00:00 2001 From: David Kellum Date: Tue, 26 Feb 2019 10:55:09 -0800 Subject: [PATCH 8/9] rfc: More motivation, two customization arguments for `-v` design --- rfcs/0001-inline-expression-value-logging.md | 177 ++++++++++++++----- 1 file changed, 135 insertions(+), 42 deletions(-) diff --git a/rfcs/0001-inline-expression-value-logging.md b/rfcs/0001-inline-expression-value-logging.md index aa4390f33..29facfb91 100644 --- a/rfcs/0001-inline-expression-value-logging.md +++ b/rfcs/0001-inline-expression-value-logging.md @@ -38,8 +38,73 @@ It follows that for projects that _do already have_ `log` and an output logger dependency and configuration, and particularly with some debug/trace logging already in place, use of `std::dbg!` would be unwelcome in PRs, and likely less productive than a `log`-based -equivalent. For parity of convenience, the `log` API needs an -extension for logging expressions and passing through values inline. +equivalent. + +## `std::dbg!` doesn't work well in projects with `log` configured + +In the context of unit tests, when using `cargo test`, _stderr_ (or +_stdout_) configured log output isn't captured, while `dbg!`, at least +when used within the tests, is captured. For passing tests, only log +output will be shown. For failing tests, log and `dbg!` output are +shown out of order, with `dbg!` captured and buffered for output at +the end of the test. + +A workaround is the rather elusive `cargo test -- --nocapture` flags, +while selecting a single test by name or using `-j 1` (single thread) +to prevent interleaving of output. But even with these workarounds in +place, or in the context of examples or other executables: + +* The output 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. + +* Other log metadata or output options like module name (`target`) or + thread names are not available with `dbg!` + +Below, us an excerpt of a debugging session combining `log::trace!`, +`log::debug!`, and `std::dbg!`: + +```txt +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 +``` + +With `std::dbg!` released, there is intrinsic value in offering +developers parity and convenience with an extension to `log` for +inline expression and value logging. # Detailed Design @@ -51,29 +116,38 @@ expression argument, which is evaluated exactly once, regardless of if the logging level is enabled or not, and returned: ```rust -let n = 12; -let m = debugv!(n / 2) - 1; -// ^-- debug log message: "n / 2 = 6" -assert_eq!(m, 5); +use std::time::{Duration, Instant}; + +let remaining = debugv!(deadline - Instant::now()); +// ^-- debug log: deadline - Instant::now() → 950µs +debugv!(remaining); +// or ^-- debug log: remaining → 950µs ``` -The _default_ format string for the _-v_ macros is `"{} = {:?}"`, +The _default_ format string for the _-v_ macros is `"{} → {:?}"`, where the `stringify!`-ed expression and resulting value are passed, in that order. Note that the `std::dbg!` macro currently uses `"{} = {:#?}"`—the value is "pretty-printed", potentially over multiple lines. Given the line-orientation of logging output, the default -format for the _-v_ macros avoids this. However, a custom format may -also be passed before the expression, which adds considerably more -output flexibility: +format for the _-v_ macros avoids this. Also we use U+2192 RIGHTWARDS +ARROW (→) as a format separator, which is more easily distinguished +from any commonly typed log message or rust expression. The log +record can be customized via two optional parameters: a message prefix +string, and a format specifier for the value. Note that the former is +required, if passing the later: ```rust let i = 32; -tracev!("{} = {}", i); // use `Display` instead of `Debug` -tracev!("{} = {:x}", i); // hexadecimal format value -tracev!("{} = {:#?}", i); // use pretty, multi-line format -let rem = infov!("{1:?} remaining ({0})", deadline - Instance::now()); - // value first, with additional context +infov!(i); +infov!("", "{:?}", i); // equivalent to above +// ^------------------------ info log: i → 32 +infov!("index", i); // contextual prefix specified +infov!("index", "{}", i); // use `Display` instead of `Debug` +// ^------------------------ info log: index i → 32 +infov!("index", "{:#x}", i); // hexadecimal format value +// ^------------------------ info log: index i → 0x20 +infov!("index", "{:#?}", i); // use pretty, multi-line format ``` For symmetry with the existing `log!` macro, a `logv!` is also @@ -92,6 +166,35 @@ assert_eq!(j, 16); See also the [implementation PR], which includes guide level documentation, in the form of rustdoc with doc-tests. +# Expected Usage + +Like with `dbg!`, its appropriate to add, then shortly remove, uses of +the _-v_ macros, or to iteratively replace _-v_ macros with the non-v +macro's (low edit distance) for nicer formatting or more English +context. 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 is just a bonus of inclusion in `log`. Its also perfectly +appropriate to use the _-v_ macros in statement position (including as +per above design examples). + +With the feature in place, while developing and debugging code: + +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 + with the existing message formatting macros in statement position, + making the messages more like English sentences. + +3. Check-in (`git commit`) 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. Iteratively repeat with step (1), possibly in parallel with other + developers. + # Alternatives ## Multiple expression support @@ -112,8 +215,9 @@ aspect][2361-single]: In relation to the proposed design of this RFC, accepting multiple expressions would also be at odds with allowing an optional custom format string as a preceding parameter. To support both would require -an additional marker, e.g. `debugv!(format: "{} = {:x}", i, j)`, as -further complication and bulk. +an additional markers, e.g. +`debugv!(prefix: "context", format: "{:x}", i, j)`, for further +complication and bulk. As suggested in RFC 2361, explicitly passing a multiple expression tuple works when desired, and avoids complications to both the @@ -122,9 +226,9 @@ syntax and macro implementation: ```rust let j = 19; let (q, r) = debugv!((j/4, j%4)); -\\ ^-- debug log message: (j / 4, j % 4) = (4, 3) -let (q, r) = debugv!("quarter {} = {:?}", (j/4, j%4)); -\\ ^-- debug log message: quarter (j / 4, j % 4) = (4, 3) +\\ ^-- debug log message: (j / 4, j % 4) → (4, 3) +let (q, r) = debugv!("quarter", (j/4, j%4)); +\\ ^-- debug log message: quarter (j / 4, j % 4) → (4, 3) assert_eq!(q, 4); assert_eq!(r, 3); ``` @@ -137,7 +241,7 @@ syntax, such as the following: ```rust debug!(= n/2) -trace!("{} = {:x}", =i); +trace!("index", =i); ``` Here the `=` signals that the expression should be `stringify!`-ed for @@ -149,30 +253,19 @@ compact. Comprehension is aided when the macro arguments are as function-like as possible, with macros specific to the feature, as designed above. -## Only customize the value part of the format - -As proposed above, the entire format string may be customized. Until -understanding that the single `i` argument is expanded to two -arguments for formatting, it is surprising to see the following, as -used above, with two placeholders in the format string: - -``` rust -tracev!("{} = {:x}", i); -``` +## Allow customizing the entire format -A workable alternative would be to only allow customizing the value -part of the format, and with the expression part fixed as `"{} ="`: +Originally this RFC allowed customizing (and required, for any +customization) the entire format string, in the form: ``` rust -tracev!("{:x}", i); +tracev!("contextual prefix: {} = {:x}", i); ``` -While this alternative is more compact for the subset of compatible -use cases, it offers less customization options. For example, it does -not support adding a custom literal prefix to the message, for additional -context. It is also less symmetric with the _formatted logging_ -macros, where the format string literal represents the _entire_ text -message of the log `Record`. +Since specifying a contextual prefix should be much more common then +changing the value or expression format; in the interest of +convenience, the design was changed to use two separate optional +customization parameters, for the prefix and value format. ## Release this as a separate crate, not in `log` @@ -198,8 +291,8 @@ macro(s), at least in 2018 edition projects, adding this feature to _-v_ macros will likely need to be adapted, when structured logging is implemented ([log RFC 296]). -The [implementation PR] (as of this writing) adds just 65 lines -of non-test code, all of which is `macro_rules!`. +The [implementation PR] (as of this writing) adds just 86 lines of +non-test code, all of which is `macro_rules!`. # Unresolved Questions From a3549d1929802ce0479fa040b4af574486b05285 Mon Sep 17 00:00:00 2001 From: David Kellum Date: Sat, 2 Mar 2019 11:46:35 -0800 Subject: [PATCH 9/9] Clarify test capture problems and combined output, with links --- rfcs/0001-inline-expression-value-logging.md | 60 +++++++++++++------- 1 file changed, 40 insertions(+), 20 deletions(-) diff --git a/rfcs/0001-inline-expression-value-logging.md b/rfcs/0001-inline-expression-value-logging.md index 29facfb91..c32e6911c 100644 --- a/rfcs/0001-inline-expression-value-logging.md +++ b/rfcs/0001-inline-expression-value-logging.md @@ -42,32 +42,52 @@ equivalent. ## `std::dbg!` doesn't work well in projects with `log` configured -In the context of unit tests, when using `cargo test`, _stderr_ (or -_stdout_) configured log output isn't captured, while `dbg!`, at least -when used within the tests, is captured. For passing tests, only log -output will be shown. For failing tests, log and `dbg!` output are -shown out of order, with `dbg!` captured and buffered for output at -the end of the test. - -A workaround is the rather elusive `cargo test -- --nocapture` flags, -while selecting a single test by name or using `-j 1` (single thread) -to prevent interleaving of output. But even with these workarounds in -place, or in the context of examples or other executables: +In the context of unit tests, the `cargo test` harness attempts to +capture _stderr_/_stdout_ independently for each test, but the +mechanism is incomplete and fragile: Output from threads other than +the test thread _escapes_ the capture, as does the output of most all +logger implementations, even when on the test thread. Interest in +fixing this has most recently been subsumed by +[_Tracking issue for eRFC 2318, Custom test frameworks_, rust-lang/rust#50297 (comment)][issue 50297]—but +with no clear commitment to a complete implementation and fix. + +This results in the practical issue that mixing `log` output with +`println!`, `eprintln!`, or `std::dbg!` results in confusing +buffering, with only the latter being captured. When tests pass, only `log` +output will be shown. When tests fail, `log` and `std::dbg!` output are +both shown, but out of order, with `std::dbg!` captured and buffered +for output after the test panics. + +For new users of `log` this can be particularly confusing, since they +are often working through their own project bugs while at the same +time trying to understand this inconsistent `cargo test` behavior. + +In such mixed usage, no capture is must less confusing than +partial/broken output capture, so the rather elusive and fun to type +`cargo test -- --nocapture --test-threads=1` can suffice as a +workaround. Anecdotally: The author finally discovered the last flag +of this puzzle just rencently, and previously was incorrectly using the +_documented_ `-j 1` flag. + +Even with the hard-earned knowledge of these workarounds, or if test +output capture eventually becomes reliable, when mixing `std::dbg!` with +`log`: * The output 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. + which is effectively 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. +* `std::dbg!` isn't beholden to `log`'s level or other filtering and + thus can't be reasonably kept in a project, at least outside of test + code. * Other log metadata or output options like module name (`target`) or thread names are not available with `dbg!` -Below, us an excerpt of a debugging session combining `log::trace!`, +Below is an excerpt of a debugging session combining `log::trace!`, `log::debug!`, and `std::dbg!`: ```txt @@ -78,8 +98,7 @@ 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 { +[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, @@ -102,9 +121,9 @@ TRACE tokio_threadpool::worker: sleeping -- push to stack; idx=1 TRACE tokio_threadpool::worker: -> starting to sleep; idx=1 ``` -With `std::dbg!` released, there is intrinsic value in offering -developers parity and convenience with an extension to `log` for -inline expression and value logging. +With `std::dbg!` released, there is now intrinsic value in at least +offering developers parity and convenience with an extension to `log` +for inline expression and value logging. # Detailed Design @@ -303,3 +322,4 @@ None. [log RFC 296]: https://github.com/rust-lang-nursery/log/pull/296 [implementation PR]: https://github.com/rust-lang-nursery/log/pull/316 [2361-single]: https://github.com/rust-lang/rfcs/blob/master/text/2361-dbg-macro.md#accepting-a-single-expression-instead-of-many +[issue 50297]: https://github.com/rust-lang/rust/issues/50297#issuecomment-388988381