New panic with env_logger and with #[windows_subsystem = "windows"]

[parasyte]

This was initially reported in rust-cli/env_logger#214, but I'm adding it here for additional eyes and because this issue doesn't occur on stable Rust. I could be wrong but this looks like this is caused by #87329 ... cc @sunfishcode ?

---

I spent an hour trying to reduce a minimal test case for this error I started experiencing with my app. So far I have produced the following:

[package]
name = "windows_explodey"
version = "0.1.0"
edition = "2018"
resolver = "2"

[dependencies]
env_logger = "0.9"

[profile.release]
panic = "abort"

#![windows_subsystem = "windows"]

fn main() {
    env_logger::init();

    println!("Hello, world!");
}

When running this on any nightly compiler since nightly-2021-08-21, I get an error like this:

$ cargo +nightly-2021-08-21 run
    Finished dev [unoptimized + debuginfo] target(s) in 0.03s
     Running `target\debug\windows_explodey.exe`
error: process didn't exit successfully: `target\debug\windows_explodey.exe` (exit code: 101)

Adjusting the profile to panic = "abort" causes an even more ominous error:

$ cargo +nightly-2021-08-21 run --release
    Finished release [optimized] target(s) in 0.03s
     Running `target\release\windows_explodey.exe`
error: process didn't exit successfully: `target\release\windows_explodey.exe` (exit code: 0xc0000409, STATUS_STACK_BUFFER_OVERRUN)

Here's a stack trace from windbg:

[0x0]   windows_explodey!panic_abort::__rust_start_panic::abort + 0x5   
[0x1]   windows_explodey!panic_abort::__rust_start_panic + 0x6   
[0x2]   windows_explodey!std::panicking::rust_panic + 0x1b   
[0x3]   windows_explodey!std::panicking::rust_panic_with_hook + 0x297   
[0x4]   windows_explodey!std::panicking::begin_panic_handler::closure$0 + 0x6f   
[0x5]   windows_explodey!std::sys_common::backtrace::__rust_end_short_backtrace<std::panicking::begin_panic_handler::closure$0,never$> + 0x17   
[0x6]   windows_explodey!std::panicking::begin_panic_handler + 0x49   
[0x7]   windows_explodey!core::panicking::panic_fmt + 0x30   
[0x8]   windows_explodey!core::panicking::panic + 0x4c   
[0x9]   windows_explodey!std::os::imp::windows::io::handle::impl$11::from_raw_handle + 0x4c   
[0xa]   windows_explodey!std::os::imp::windows::io::raw::impl$7::from_raw_handle + 0x13   
[0xb]   windows_explodey!winapi_util::win::HandleRef::from_raw_handle + 0xe   
[0xc]   windows_explodey!winapi_util::win::HandleRef::stderr + 0x27   
[0xd]   windows_explodey!winapi_util::console::HandleKind::handle + 0x27   
[0xe]   windows_explodey!winapi_util::console::Console::create_for_stream + 0x22   
[0xf]   windows_explodey!winapi_util::console::Console::stderr + 0x1d   
[0x10]   windows_explodey!termcolor::BufferWriter::create + 0x59   
[0x11]   windows_explodey!termcolor::BufferWriter::stderr + 0x22   
[0x12]   windows_explodey!env_logger::fmt::writer::termcolor::imp::BufferWriter::stderr + 0x49   
[0x13]   windows_explodey!env_logger::fmt::writer::Builder::build + 0x133   
[0x14]   windows_explodey!env_logger::Builder::build + 0x46   
[0x15]   windows_explodey!env_logger::Builder::try_init + 0x1c   
[0x16]   windows_explodey!env_logger::try_init_from_env<env_logger::Env> + 0x39   
[0x17]   windows_explodey!env_logger::try_init + 0x1b   
[0x18]   windows_explodey!env_logger::init + 0x9   
[0x19]   windows_explodey!windows_explodey::main + 0x9   

If I'm reading this correctly, the panic is from this assertion:

rust/library/std/src/os/windows/io/handle.rs

Line 183 in 50171c3

assert!(!handle.is_null());

[ChrisDenton]

Likely cause is that when the "windows" subsystem is used, the std handles will all be null (i.e. they don't exist). From the backtrace it looks like something is expecting them to always be a valid handle value.

EDIT: Oh wait, that's probably termcolor not checking for null before making a BufferWriter?

[parasyte]

termcolor just does this: https://github.com/BurntSushi/termcolor/blob/dc7e7b93830579716fc180925a17551dee5cfddc/src/lib.rs#L893-L899

It expects a Result.

[sunfishcode]

winapi-util does this: https://github.com/BurntSushi/winapi-util/blob/master/src/win.rs#L139

It assumes it can call as_raw_handle and get something it can pass to from_raw_handle. as_raw_handle calls GetStdHandle which returns NULL if there are no handles, as in "windows" subsystem mode, and then the new from_raw_handle code asserts that its argument is non-null.

[sunfishcode]

The crash goes away if I change the env_logger dependency in Cargo.toml to disable the "termcolor" and "atty" features:

env_logger = { version = "0.9", default-features = false, features = ["humantime", "regex"] }

As such, one option here would be to say that io::stderr() shouldn't be called in #![windows_subsystem = "windows"] mode, and have it panic with a descriptive panic message. There's a logic to that, since there seems to be no point in linking in and calling termcolor or other stdio-using things if there's no terminal to talk to. However, that's not backwards compatible.

Another option would be to say that OwnedHandle::from_raw_handle has to be able to accept NULL handles. That's doable, though if we want to preserve the FFI use case, that would mean introducing another struct like HandleOrInvalid, this time for NULL instead of INVALID_HANDLE_VALUE.

[sunfishcode]

cc the io_safety tracking issue

[parasyte]

Maybe it would be worthwhile to get BurntSushi's thoughts, since this affects winapi_util?

Personally I would be ok with "just update your dependencies" as a solution, but maintaining backward compatibility might be more important for the libraries team...

[ChrisDenton]

As such, one option here would be to say that io::stderr() shouldn't be called in #![windows_subsystem = "windows"] mode, and have it panic with a descriptive panic message. There's a logic to that, since there seems to be no point in linking in and calling termcolor or other stdio-using things if there's no terminal to talk to. However, that's not backwards compatible.

In any case this would cause other problems. Windows processes can be freely attached or detached from consoles no mater which windows_subsystem they're using so we can't really make assumptions based on that.

[sunfishcode]

In any case this would cause other problems. Windows processes can be freely attached or detached from consoles no mater which windows_subsystem they're using so we can't really make assumptions based on that.

In that case, it seems like the best option is to change OwnedHandle to accept null. And for the FFI use case, introduce a new HandleOrNull struct similar to HandleOrInvalid but for functions that use NULL to indicate an error.

[ChrisDenton]

Hm, GetStdHandle uses INVALID_HANDLE_VALUE to indicate an error and NULL to indicate there's no associated handle.

[sunfishcode]

Good catch; HandleOrInvalid will also need to be changed to accept NULL handles.

[sunfishcode]

This is now implemented in #88798.

[joshtriplett]

@sunfishcode Would it make sense to just use Option<HandleOrInvalid> for that?

[sunfishcode]

@joshtriplett User code like this means that BorrowedHandle needs to be able to hold a null, in windows_subsystem = "windows" mode. Then, ManuallyDrop and IntoHandle in Drop idioms imply that OwnedHandle needs to be able to hold any value that BorrowedHandle can hold.

[ChrisDenton]

Ideally stdout() etc would return an Option (or io::Result I guess). But seeing as that's not the case, this is probably the best solution. Or I guess it could return a handle to the \\.\NUL device? That might cause more problems though.

[sunfishcode]

I agree, returning a handle to \\.\NUL would be a significant change from how std currently works, and would likely break code that expects to be able to test std::io::stdout() and similar for null to see if a console is attached.

@joshtriplett Is there anything else I should investigate here?

[joshtriplett]

This makes me sad, but this makes sense. I don't think this needs further investigation.

I posted a bit of code review on the PR, but otherwise this should probably go ahead.

[parasyte]

FYI, this bug made it to stable 1.56.0 today.

[wez]

Is the resolution for this to pin on Rust 1.55 until 1.57 is released?

[sunfishcode]

Yes, I expect that's the best thing we can do for now. The real fix is #88798. Once that's reviewed and landed, I'll ask about backporting it.

[Mark-Simulacrum]

Is there a fix landed yet (e.g., does nightly work)? If so, we can discuss backporting it -- I've temporarily added a 1.57 milestone (to make sure we take a look before that ships), as this was previously not tracked as a regression and so did not receive the appropriate attention for the 1.56 release where it regressed originally.

[glandium]

removed regression-from-stable-to-stable

why? this is a regression that shipped in 1.56!

[Mark-Simulacrum]

My bad. I looked at the milestone and was worried it might've been mislabeled (by me) but I don't think that's actually the case.

[joshtriplett]

I'll review the fix today.

[Subsentient]

I'll review the fix today.

Thank you Josh, it's much appreciated. The GUI target for the most popular OS being broken is a pretty severe thing imho (since so many crates use env_logger automatically), so definitely don't want that staying broken too long. I guess most Rustaceans don't use Rust on Windows, because I'm surprised no one has been yelling bloody murder about this bug. I only found it after trying to compile a release build of my employer's project.

[joshtriplett]

@Subsentient Many Rustaceans use Windows, and many build non-CLI apps, but I have the impression many do not combine that with things that get stdout handles.

[parasyte]

This is the kind of issue that you are likely to hit accidentally as mentioned in #88576 (comment). Not specifically because you are building a Windows GUI application that also writes to stdout.

[Subsentient]

This is the kind of issue that you are likely to hit accidentally as mentioned in #88576 (comment). Not specifically because you are building a Windows GUI application that also writes to stdout.

Correct, it seems a sizable percentage of crates initialize env_logger on their own, which means that if you're building a non-trivial application, odds are high that you'll hit this bug. Or maybe you just get lucky? But two of my non-trivial projects with no crates in common are hitting this bug. In other words, this bug is more urgent than it may have first appeared to maintainers.

[sunfishcode]

#88798 has now landed, the latest Rust nightly (936238a) now includes it, and using that, I can compile and run the testcase successfully.

[sunfishcode]

I'm following the steps documented here for backporting changes to beta.

[cuviper]

Backported in #90938.

[sunfishcode]

Rust 1.57, which was just released, contains the fix for this. I've confirmed that the testcase reported here is fixed.