0001-inline-expression-value-logging.md

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, as implemented in rust 1.32. To summarize:

• 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.

• 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!, 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 Levels, 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.

std::dbg! doesn't work well in projects with log configured

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)—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 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 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 is an excerpt of a debugging session combining log::trace!, log::debug!, and std::dbg!:

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

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

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:

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 "{} → {:?}", 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. 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:

let i = 32;

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 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 literal:

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.

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

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:

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 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 syntax and macro implementation:

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

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:

debug!(= n/2)
trace!("index", =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. Comprehension is aided when the macro arguments are as function-like as possible, with macros specific to the feature, as designed above.

Allow customizing the entire format

Originally this RFC allowed customizing (and required, for any customization) the entire format string, in the form:

tracev!("contextual prefix: {} = {:x}", i);

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

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. 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 86 lines of non-test code, all of which is macro_rules!.

Unresolved Questions

None.