Formatting of std::backtrace::Backtrace

[seanmonstar]

I'd like to propose some changes to formatting of the Backtrace type introduced in #53487.

• Don't include newlines in the default Debug output. I personally find it pretty jarring when looking at the debug output of an error where everything is on the same line except the backtrace, and then any additional properties are printed way down on the last line.

  I'd suggest instead printing a "list" of "maps", such that it'd look like [{ function: "errors::new", file: "./src/new.rs", line: 21 }, ...].

• Allow passing the "precision" format flag to limit how many frames are printed. The most relevant frames are normally near the top, but deciding exactly how many depends on the app. Then a user could write println!("short trace: {:.5}", trace) to see just 5 frames.

• Remove stack backtrace:\n prefix entirely. When formatting, I'd think a user would pick their own prefix, like println!("Call stack:\n{}", trace).

[dtolnay]

+1 to all three points. I would accept a PR for this change.

[0paIescent]

I'd like to take on this issue and make a PR for it. This is my first time taking on a PR for rust though, so is there anything you'd suggest outside of the Contributing guide?

[seanmonstar]

I think this requires edits in libstd (

rust/src/libstd/backtrace.rs

Lines 269 to 323 in 437ca55

	impl fmt::Display for Backtrace {
	fn fmt(&self, fmt: &mut fmt::Formatter<'_>) -> fmt::Result {
	fmt::Debug::fmt(self, fmt)
	}
	}
	impl fmt::Debug for Backtrace {
	fn fmt(&self, fmt: &mut fmt::Formatter<'_>) -> fmt::Result {
	let mut capture = match &self.inner {
	Inner::Unsupported => return fmt.write_str("unsupported backtrace"),
	Inner::Disabled => return fmt.write_str("disabled backtrace"),
	Inner::Captured(c) => c.lock().unwrap(),
	};
	capture.resolve();
	let full = fmt.alternate();
	let (frames, style) = if full {
	(&capture.frames[..], backtrace::PrintFmt::Full)
	} else {
	(&capture.frames[capture.actual_start..], backtrace::PrintFmt::Short)
	};
	// When printing paths we try to strip the cwd if it exists, otherwise
	// we just print the path as-is. Note that we also only do this for the
	// short format, because if it's full we presumably want to print
	// everything.
	let cwd = crate::env::current_dir();
	let mut print_path = move |fmt: &mut fmt::Formatter<'_>, path: BytesOrWideString<'_>| {
	output_filename(fmt, path, style, cwd.as_ref().ok())
	};
	let mut f = backtrace::BacktraceFmt::new(fmt, style, &mut print_path);
	f.add_context()?;
	for frame in frames {
	let mut f = f.frame();
	if frame.symbols.is_empty() {
	f.print_raw(frame.frame.ip(), None, None, None)?;
	} else {
	for symbol in frame.symbols.iter() {
	f.print_raw(
	frame.frame.ip(),
	symbol.name.as_ref().map(|b| backtrace::SymbolName::new(b)),
	symbol.filename.as_ref().map(|b| match b {
	BytesOrWide::Bytes(w) => BytesOrWideString::Bytes(w),
	BytesOrWide::Wide(w) => BytesOrWideString::Wide(w),
	}),
	symbol.lineno,
	)?;
	}
	}
	}
	f.finish()?;
	Ok(())
	}
	}

), and in the backtrace crate (https://github.com/rust-lang/backtrace-rs/blob/master/src/print.rs).

[0paIescent]

Thanks! I had already looked into it though, I meant more of general contribution to Rust 😄

[0paIescent]

How's this looking?

[{ function: "debug::backtrace_should_debug", file: "tests/debug.rs", line: 5 }, { function: "debug::backtrace_should_debug::{{closure}}", file: "tests/debug.rs", line: 4 }, { function: "core::ops::function::FnOnce::call_once", file: "/rustc/eae3437dfe991621e8afdc82734f4a172d7ddf9b/src/libcore/ops/function.rs", line: 231 }, { function: "<alloc::boxed::Box<F> as core::ops::function::FnOnce<A>>::call_once", file: "/rustc/eae3437dfe991621e8afdc82734f4a172d7ddf9b/src/liballoc/boxed.rs", line: 746 }, { function: "__rust_maybe_catch_panic", file: "src/libpanic_unwind/lib.rs", line: 82 }, { function: "std::panicking::try", file: "/rustc/eae3437dfe991621e8afdc82734f4a172d7ddf9b/src/libstd/panicking.rs", line: 275 }, { function: "std::panic::catch_unwind", file: "/rustc/eae3437dfe991621e8afdc82734f4a172d7ddf9b/src/libstd/panic.rs", line: 394 }, { function: "test::run_test::run_test_inner::{{closure}}", file: "src/libtest/lib.rs", line: 1466 }, { function: "std::sys_common::backtrace::__rust_begin_short_backtrace", file: "/rustc/eae3437dfe991621e8afdc82734f4a172d7ddf9b/src/libstd/sys_common/backtrace.rs", line: 77 }, { function: "std::thread::Builder::spawn_unchecked::{{closure}}::{{closure}}", file: "/rustc/eae3437dfe991621e8afdc82734f4a172d7ddf9b/src/libstd/thread/mod.rs", line: 470 }, { function: "<std::panic::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once", file: "/rustc/eae3437dfe991621e8afdc82734f4a172d7ddf9b/src/libstd/panic.rs", line: 315 }, { function: "std::panicking::try::do_call", file: "/rustc/eae3437dfe991621e8afdc82734f4a172d7ddf9b/src/libstd/panicking.rs", line: 296 }, { function: "__rust_maybe_catch_panic", file: "src/libpanic_unwind/lib.rs", line: 82 }, { function: "std::panicking::try", file: "/rustc/eae3437dfe991621e8afdc82734f4a172d7ddf9b/src/libstd/panicking.rs", line: 275 }, { function: "std::panic::catch_unwind", file: "/rustc/eae3437dfe991621e8afdc82734f4a172d7ddf9b/src/libstd/panic.rs", line: 394 }, { function: "std::thread::Builder::spawn_unchecked::{{closure}}", file: "/rustc/eae3437dfe991621e8afdc82734f4a172d7ddf9b/src/libstd/thread/mod.rs", line: 469 }, { function: "core::ops::function::FnOnce::call_once{{vtable.shim}}", file: "/rustc/eae3437dfe991621e8afdc82734f4a172d7ddf9b/src/libcore/ops/function.rs", line: 231 }, { function: "<alloc::boxed::Box<F> as core::ops::function::FnOnce<A>>::call_once", file: "/rustc/eae3437dfe991621e8afdc82734f4a172d7ddf9b/src/liballoc/boxed.rs", line: 746 }, { function: "<alloc::boxed::Box<F> as core::ops::function::FnOnce<A>>::call_once", file: "/rustc/eae3437dfe991621e8afdc82734f4a172d7ddf9b/src/liballoc/boxed.rs", line: 746 }, { function: "std::sys_common::thread::start_thread", file: "src/libstd/sys_common/thread.rs", line: 13 }, { function: "std::sys::unix::thread::Thread::new::thread_start", file: "src/libstd/sys/unix/thread.rs", line: 79 }, { function: "start_thread" }, { function: "__clone" }, ]

[dtolnay]

The trailing comma at the end looks wrong }, ]. It should be }].

Could you share the println!("{:#?}", backtrace) prettyprinted representation too?

[0paIescent]

Yeah I'm working on getting that out of there, I was starting with just modifying the write!()s, but I wonder if more of a redesign is needed.

And here it is prettyprinted:

[{ function: "backtrace::backtrace::libunwind::trace::h48ac50731a0a91de", file: "src/backtrace/libunwind.rs", line: 88 }, { function: "backtrace::backtrace::trace_unsynchronized::h4559afe57f03b771", file: "src/backtrace/mod.rs", line: 66 }, { function: "backtrace::backtrace::trace::hc39710a32530e8a8", file: "src/backtrace/mod.rs", line: 53 }, { function: "backtrace::capture::Backtrace::create::h145883c532efd462", file: "src/capture.rs", line: 164 }, { function: "backtrace::capture::Backtrace::new::hdd6faab09de669a5", file: "src/capture.rs", line: 128 }, { function: "debug::backtrace_should_debug::h0ba343c1a82ecb0f", file: "tests/debug.rs", line: 5 }, { function: "debug::backtrace_should_debug::{{closure}}::hda5c810039ce23ab", file: "tests/debug.rs", line: 4 }, { function: "core::ops::function::FnOnce::call_once::h664a0e00eff51220", file: "/rustc/eae3437dfe991621e8afdc82734f4a172d7ddf9b/src/libcore/ops/function.rs", line: 231 }, { function: "<alloc::boxed::Box<F> as core::ops::function::FnOnce<A>>::call_once::h4a13ee3f0d7b4201", file: "/rustc/eae3437dfe991621e8afdc82734f4a172d7ddf9b/src/liballoc/boxed.rs", line: 746 }, { function: "__rust_maybe_catch_panic", file: "src/libpanic_unwind/lib.rs", line: 82 }, { function: "std::panicking::try::h5a93466ab2078586", file: "/rustc/eae3437dfe991621e8afdc82734f4a172d7ddf9b/src/libstd/panicking.rs", line: 275 }, { function: "std::panic::catch_unwind::h752cbeae6ac7bdea", file: "/rustc/eae3437dfe991621e8afdc82734f4a172d7ddf9b/src/libstd/panic.rs", line: 394 }, { function: "test::run_test::run_test_inner::{{closure}}::h206c9c16936edaca", file: "src/libtest/lib.rs", line: 1466 }, { function: "std::sys_common::backtrace::__rust_begin_short_backtrace::hc7edbac42990d270", file: "/rustc/eae3437dfe991621e8afdc82734f4a172d7ddf9b/src/libstd/sys_common/backtrace.rs", line: 77 }, { function: "std::thread::Builder::spawn_unchecked::{{closure}}::{{closure}}::he53c58e7adee87af", file: "/rustc/eae3437dfe991621e8afdc82734f4a172d7ddf9b/src/libstd/thread/mod.rs", line: 470 }, { function: "<std::panic::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once::h1aff7c42b6bb3726", file: "/rustc/eae3437dfe991621e8afdc82734f4a172d7ddf9b/src/libstd/panic.rs", line: 315 }, { function: "std::panicking::try::do_call::h41f8559f88100f6c", file: "/rustc/eae3437dfe991621e8afdc82734f4a172d7ddf9b/src/libstd/panicking.rs", line: 296 }, { function: "__rust_maybe_catch_panic", file: "src/libpanic_unwind/lib.rs", line: 82 }, { function: "std::panicking::try::hb54ba808181fe352", file: "/rustc/eae3437dfe991621e8afdc82734f4a172d7ddf9b/src/libstd/panicking.rs", line: 275 }, { function: "std::panic::catch_unwind::h555ccf4e835e93f4", file: "/rustc/eae3437dfe991621e8afdc82734f4a172d7ddf9b/src/libstd/panic.rs", line: 394 }, { function: "std::thread::Builder::spawn_unchecked::{{closure}}::hd4dae6e19e80fc1a", file: "/rustc/eae3437dfe991621e8afdc82734f4a172d7ddf9b/src/libstd/thread/mod.rs", line: 469 }, { function: "core::ops::function::FnOnce::call_once{{vtable.shim}}::hc35d54c07710e1a1", file: "/rustc/eae3437dfe991621e8afdc82734f4a172d7ddf9b/src/libcore/ops/function.rs", line: 231 }, { function: "<alloc::boxed::Box<F> as core::ops::function::FnOnce<A>>::call_once::h42806b83647d4c79", file: "/rustc/eae3437dfe991621e8afdc82734f4a172d7ddf9b/src/liballoc/boxed.rs", line: 746 }, { function: "<alloc::boxed::Box<F> as core::ops::function::FnOnce<A>>::call_once::h83c921c8e826dd1d", file: "/rustc/eae3437dfe991621e8afdc82734f4a172d7ddf9b/src/liballoc/boxed.rs", line: 746 }, { function: "std::sys_common::thread::start_thread::h2613204ce513782e", file: "src/libstd/sys_common/thread.rs", line: 13 }, { function: "std::sys::unix::thread::Thread::new::thread_start::h4570080769500bcd", file: "src/libstd/sys/unix/thread.rs", line: 79 }, { function: "start_thread" }, { function: "__clone" }, { function: "<unknown>" }, ]

[seanmonstar]

You can get a lot of this for "free" if you make use of Formatter::debug_list() and make a wrapper DebugFrame<'a>(&'a Frame).

fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
    f.debug_list()
        .entries(backtrace.frames.iter().map(|f| DebugFrame(f)))
        .finish()
}

And in DebugFrame, you can use Formatter::debug_struct.

[0paIescent]

Oh that's a great idea, I had forgotten those helper methods were there in Debug. Thanks!

[0paIescent]

Here's my fork with what I have so far for backtrace-rs. Now, the reason there was a trailing comma at the end was that the last frame had a IP of 0x0, and its symbol had no data. Do those need to be filtered out or is there a practical use for those?

Also, the one thing left besides precision is getting the path properly, but before it was done by being passed in to BacktraceFmt. Do you have some suggestions for how I could get that into the DebugBacktraceSymbol in a more efficient way than just passing it down through the DebugBacktraceFrame and then down into the DebugBacktraceSymbol?

[0paIescent]

So, I changed it back to the previous way of printing everything out, just with some added formatting, and a check to see if it's the first frame so it knows when to print a comma after a symbol's "map".

The precision also works now, but there's a catch, since the formatter is passed down to the print path function the precision persists when printing out the path. Since Formatter doesn't have setters for its attributes, what else could I do to update the precision to None other than just making a PR for a setter for precision?

[seanmonstar]

My idea using precision might not end up working well...

[0paIescent]

Actually..

Here's what it's doing now fmt::Display::fmt(&path.display, fmt)
Instead why not just use write!(fmt, "{}", &path.display()) and format it with no precision and write that to the formatter

[clouds56]

What about indent? println!("short trace: {:2.5}", trace) means 5 frames, 2 spaces for indent per line.

[liranringel]

@dtolnay I believe this issue is resolved?
Should update #53487

[withoutboats]

@dtolnay @seanmonstar is this issue resolved?

[seanmonstar]

Probably! Of the points I posted originally:

• There is now a typical Debug format that doesn't force newlines and respects :#?.
• We can't use formatting's precision feature to restrict the amount of frames shown, which would be super useful (I suspect the first 5 or so are the most interesting, the rest is noise). But there's an issue with the precision flag propagating to each line, making the filenames and such cut short too... I'd be fine with this being a separate issue.
• The stack bactrace:\n prefix has been removed, so a user can call it something different if the prefer (call stack, frames, etc).

[yaahc]

Would adding the precision stuff later be considered a breaking change that violates std's stability guaruntees?

[withoutboats]

IMO currently the only guarantee we're making about backtrace is that formatted with the normal Debug formatting ("{:?}") will not change. In the worst case (though this shouldn't happen), the API could instead be a new method on backtrace which returns a view of only a range of ranges.

[Mark-Simulacrum]

@withoutboats I would maybe not even go that far? e.g. that we probably don't want to guarantee a specific implementation wrt to showing inlined functions and such. But maybe you mean that we will keep the format of the "raw" Debug display consistent with what it is today.

I'd personally be unsure that I would want to stabilize even that -- I think if we're essentially stabilizing that I would rather stabilize accessor methods returning an iterator or something along those lines to avoid people parsing our output (and preventing any, even minor, changes as a result).

[withoutboats]

But maybe you mean that we will keep the format of the "raw" Debug display consistent with what it is today.

This should probably be on the #72981 but: users are curently relying on that format to parse out info about the frames, because we don't provide a better API. We should not break that, at least until we have stable accessors. I agree that we should provide those APIs as well, but I wouldn't agree that it should block stabilizing backtrace. I just think we should be aware that users are currently, on nightly, relying on the format of the debug output.

[Mark-Simulacrum]

Ah, I was not aware that we knew of use cases that were doing that. I agree that we should not break them just because and certainly not before methods are added to replace functionality. I also agree it need not block stabilization.

One thing that might be good to do is to add a method that explicitly keeps the current format or at least add a snippet to the Debug impl noting that we intend to keep it stable.

[yaahc]

Yea, my inclination is to not block stabilization on the filtering issue, users can already filter the frames themselves by parsing the output from the Debug impl with something like https://crates.io/crates/btparse. Also, once we get a stable access api for iterating over frames it should be easy to build filtering ontop of Backtrace and crates like color-backtrace which do more accurate filtering than the precision based filtering built into the Display impl could probably achieve.

[cauebs]

Have you guys settled on the precision idea or are you open to other approaches? Using Index with ranges seems way more intuitive to me.

[yaahc]

My impression is that we're punting on the issue and instead focusing on making it possible for ppl to experiment with their own display formats by adding a frames method to Backtrace.

[tmandry]

On Fuchsia we use external symbolization, which means the file and line number are not resolved in the process itself. This allows us to capture backtraces without having to ship binaries containing debuginfo. We use a standard symbolization markup format across the platform, where each frame is typically printed on its own line.

I'm not opposed to these changes on other platforms, but I bring this up to highlight that the Display/Debug formats of Backtrace can't be the same across all platforms and build configurations.

[philip-peterson]

@tmandry is that implemented using the Rust standard tooling or some other way? Would be nice for development on this issue to have a minimal repro case, against which to test changes to Rust on.