Formatting of std::backtrace::Backtrace

[seanmonstar]

View all comments

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