Capturing a backtrace prevents any future panic from printing a backtrace on Windows

[aloucks]

As the title states, backtraces are not printed if the program panics after a backtrace was captured with the library.

$ rustc --version -v
rustc 1.34.0 (91856ed52 2019-04-10)
binary: rustc
commit-hash: 91856ed52c58aa5ba66a015354d1cc69e9779bdf
commit-date: 2019-04-10
host: x86_64-pc-windows-msvc
release: 1.34.0
LLVM version: 8.0

With RUST_BACKTRACE=1

let bt = Backtrace::new();
println!("{:?}", bt); // <-- this backtrace is printed
panic!("Oops!");      // <-- the backtrace here is not printed

I tracked it down to this commit: 3cfb76a

The cleanup code was removed.

Changing the example to the following allows for both backtraces to print:

let bt = Backtrace::new();
println!("{:?}", bt);
unsafe {
    let handle = winapi::um::processthreadsapi::GetCurrentProcess();
    winapi::um::dbghelp::SymCleanup(handle);
}
panic!("Oops!");

The runtime panic-unwind code is checking the result of SymInitialize which is probably an error due to double initialization.

https://github.com/rust-lang/rust/blob/9ebf47851a357faa4cd97f4b1dc7835f6376e639/src/libstd/sys/windows/backtrace/mod.rs#L74

https://docs.microsoft.com/en-us/windows/desktop/api/dbghelp/nf-dbghelp-syminitializew

A process that calls SymInitialize should not call it again unless it calls SymCleanup first.

Perhaps the old behavior could be restored with deferred symbol loading:

https://docs.microsoft.com/en-us/windows/desktop/api/Dbghelp/nf-dbghelp-symsetoptions

SYMOPT_DEFERRED_LOADS0x00000004 | Symbols are not loaded until a reference is made requiring the symbols be loaded. This is the fastest, most efficient way to use the symbol handler.

Alternatively, the runtime panic-unwind code could perhaps always call SymCleanup first (and ignore the error) prior to calling SymInitialize. As far as I can tell, calling SymCleanup without first initializing returns an error code but is otherwise harmless.

[alexcrichton]

Thanks for the report! This is definitely a bug and something that should be fixed! I honestly am not sure how to best fix it and I'm not 100% clear on how this works in Windows. I think it's already technically UB beacuse we're not synchronizing with the backtrace mechanism in the standard library, but that's not necessarily the end of the world.

I think though that registering a panic hook may not be the best approach here, is there perhaps something we can do to update the standard library and/or this crate and have the two work together?

[aloucks]

I honestly am not sure how to best fix it and I'm not 100% clear on how this works in Windows.

Me neither. Everything I know about backtrace in windows was discovered yesterday evening :)

I think though that registering a panic hook may not be the best approach here

I agree! Although I do think it's better than leaving the current behavior (even if temporary).

is there perhaps something we can do to update the standard library and/or this crate and have the two work together?

Having the standard library preemptively call SymCleanup prior to initialization would fix the issue under the assumption that unwind_backtrace is only called once right before the process exits. However, I don't think that assumption holds true with the use of panic::catch_unwind.

I think that coordinating with the standard library is the right approach. Is this something that would require an RFC? And/or could it be something exposed in std::os::windows? I'm not quite sure how this could be exposed in a way that makes sense without moving all of the backtrace functionality into std.

Do you know of any examples of libraries coordinating platform specifics with the standard library?

[alexcrichton]

There's been some coordination with libstd and other librararies before, but it just doesn't really come up that often. Ironically this library has had to coordinate the most probably...

In any case after reading the code it looks like libstd already has initialize/cleanup pairings, so maybe this library should just have that as well? I believe that would fix the issue, right?

[aloucks]

I think having the initialize/cleanup pairings is a correct approach, but it does have a non-trivial performance penalty. I added the cleanup back and ran cargo test and could see the difference (and ran twice to factor out compile time). dbghelp_init is also called twice per backtrace: once for the initial stack walk and then again for the resolve.

I also tried with the SYMOPT_DEFERRED_LOADS and it made a significant difference. If the bulk of the time is in fact due to the resolve (which I would imagine most code would only resolve when a stacktrace is printed), this might be good option. Maybe we should go with this for now and revisit coordinating lazy loading and cleanup with the std library if performance issues crop up later?

master:

$ time cargo test
...
real    0m0.790s
user    0m0.000s
sys     0m0.000s

master with cleanup code added back:

$ time cargo test
...
real    0m4.891s
user    0m0.000s
sys     0m0.000s

Master with cleanup and SYMOPT_DEFERRED_LOADS:

$ time cargo test
...
real    0m2.846s
user    0m0.000s
sys     0m0.000s

// requires external synchronization
#[cfg(all(windows, feature = "dbghelp"))]
unsafe fn dbghelp_init() -> std::boxed::Box<dyn std::any::Any> {
    use winapi::shared::minwindef::{self, DWORD};
    use winapi::um::{dbghelp, processthreadsapi};
    use winapi::um::winnt::HANDLE;

    struct Cleanup { handle: HANDLE }

    impl Drop for Cleanup {
        fn drop(&mut self) {
            unsafe {
                dbghelp::SymCleanup(self.handle);
            }
        }
    }

    let handle = processthreadsapi::GetCurrentProcess();

    const SYMOPT_DEFERRED_LOADS: DWORD = 0x00000004;

    // not sure why these are missing in winapi
    extern "system" {
        fn SymGetOptions() -> DWORD;
        fn SymSetOptions(options: DWORD);
    }

    let opts = SymGetOptions();
    SymSetOptions(opts | SYMOPT_DEFERRED_LOADS);

    let ret = dbghelp::SymInitializeW(handle,
                                      0 as *mut _,
                                      minwindef::TRUE);
    if ret != minwindef::TRUE {
        std::boxed::Box::new(())
    } else {
        std::boxed::Box::new(Cleanup { handle })
    }
}

[aloucks]

It's still pretty slow to with the cleanup pairings..

#[bench]
fn new(b: &mut test::Bencher) {
    b.iter(|| {
        let bt = Backtrace::new();
        test::black_box(bt);
    });
}

#[bench]
fn new_unresolved(b: &mut test::Bencher) {
    b.iter(|| {
        let bt = Backtrace::new_unresolved();
        test::black_box(bt);
    });
}

Master:

     Running target\release\deps\new-6e89b65766b479eb.exe

running 1 test
test new ... bench:     385,830 ns/iter (+/- 94,160)

test result: ok. 0 passed; 0 failed; 0 ignored; 1 measured; 0 filtered out

     Running target\release\deps\new_unresolved-9156de942e954d9b.exe

running 1 test
test new_unresolved ... bench:     157,797 ns/iter (+/- 4,564)

test result: ok. 0 passed; 0 failed; 0 ignored; 1 measured; 0 filtered out

Master with cleanup:

     Running target\release\deps\new-6e89b65766b479eb.exe

running 1 test
test new ... bench: 199,705,370 ns/iter (+/- 8,677,602)

test result: ok. 0 passed; 0 failed; 0 ignored; 1 measured; 0 filtered out

     Running target\release\deps\new_unresolved-9156de942e954d9b.exe

running 1 test
test new_unresolved ... bench:  11,045,640 ns/iter (+/- 1,842,231)

test result: ok. 0 passed; 0 failed; 0 ignored; 1 measured; 0 filtered out

Master with cleanup and SYMOPT_DEFERRED_LOADS:

     Running target\release\deps\new-6e89b65766b479eb.exe

running 1 test
test new ... bench:  57,221,740 ns/iter (+/- 4,131,231)

test result: ok. 0 passed; 0 failed; 0 ignored; 1 measured; 0 filtered out

     Running target\release\deps\new_unresolved-9156de942e954d9b.exe

running 1 test
test new_unresolved ... bench:   5,161,505 ns/iter (+/- 333,050)

test result: ok. 0 passed; 0 failed; 0 ignored; 1 measured; 0 filtered out

[alexcrichton]

I think we've had bad performance problems with libbacktrace on other platforms as well before, so taking quite a long time during symbolication I think is expected. It's a bummer it's that slow but shouldn't be the end of the world in most cases in theory.

The backtracing portion may not actually need to call SymInitialize, I may have just written that in at some point in error!