Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

rustc -C help panics (ICEs) when piped to a closed stdout #98700

Closed
CAD97 opened this issue Jun 30, 2022 · 5 comments · Fixed by #100040
Closed

rustc -C help panics (ICEs) when piped to a closed stdout #98700

CAD97 opened this issue Jun 30, 2022 · 5 comments · Fixed by #100040
Labels
C-bug Category: This is a bug. I-ICE Issue: The compiler panicked, giving an Internal Compilation Error (ICE) ❄️ O-windows Operating system: Windows T-compiler Relevant to the compiler team, which will review and decide on the PR/issue.

Comments

@CAD97
Copy link
Contributor

CAD97 commented Jun 30, 2022

Code

rustc -C help | cmd /c exit

After more testing, this only reproduces consistently under cmd, as other Windows shells have diverging behavior about what it means to close a pipe via program termination 🙃

rustc --help | cmd /c exit does not panic, but this appears to be not because of rustc doing anything different, but because rustc finishes writing to stdout before it is closed.

Meta

Note: never occurs under #[cfg(unix)], as rustc sets SIGPIPE to SIG_DFL.

rustc_driver::set_sigpipe_handler

#[cfg(unix)]
pub fn set_sigpipe_handler() {
unsafe {
// Set the SIGPIPE signal handler, so that an EPIPE
// will cause rustc to terminate, as expected.
assert_ne!(libc::signal(libc::SIGPIPE, libc::SIG_DFL), libc::SIG_ERR);
}
}

rustc --version --verbose:

rustc 1.63.0-nightly (dc80ca78b 2022-06-21)
binary: rustc
commit-hash: dc80ca78b6ec2b6bba02560470347433bcd0bb3c
commit-date: 2022-06-21
host: x86_64-pc-windows-msvc
release: 1.63.0-nightly
LLVM version: 14.0.5

Error output

thread 'main' panicked at 'failed printing to stdout: The pipe is being closed. (os error 232)', library\std\src\io\stdio.rs:1015:9

error: internal compiler error: unexpected panic

note: the compiler unexpectedly panicked. this is a bug.

note: we would appreciate a bug report: https://github.com/rust-lang/rust/issues/new?labels=C-bug%2C+I-ICE%2C+T-compiler&template=ice.md

note: rustc 1.63.0-nightly (dc80ca78b 2022-06-21) running on x86_64-pc-windows-msvc

note: compiler flags: -C help

query stack during panic:
end of query stack
Backtrace

stack backtrace:
   0:     0x7ffecbca9dff - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::h46bec461e9e7ac22
   1:     0x7ffecbce4a4a - core::fmt::write::h2cf2927a9deb2e17
   2:     0x7ffecbc9c2e9 - <std::io::IoSliceMut as core::fmt::Debug>::fmt::hfd12a4a4f03cb21d
   3:     0x7ffecbcad6eb - std::panicking::default_hook::h22600ff9cff4f04f
   4:     0x7ffecbcad36b - std::panicking::default_hook::h22600ff9cff4f04f
   5:     0x7ffe8f597f06 - rustc_driver[9e128b4dc2b1f3f4]::pretty::print_after_hir_lowering
   6:     0x7ffecbcade92 - std::panicking::rust_panic_with_hook::hf01515033fcb4adb
   7:     0x7ffecbcadc2d - <std::panicking::begin_panic_handler::StrPanicPayload as core::panic::BoxMeUp>::get::h8d0ff84b444c4809
   8:     0x7ffecbcaaa37 - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::h46bec461e9e7ac22
   9:     0x7ffecbcad909 - rust_begin_unwind
  11:     0x7ffecbc9a185 - std::io::stdio::_print::heedac1eb9faaac98
  12:     0x7ffe8f5a34b3 - rustc_driver[9e128b4dc2b1f3f4]::handle_options
  13:     0x7ffe8f598e68 - <rustc_driver[9e128b4dc2b1f3f4]::RunCompiler>::run
  14:     0x7ffe8f5203be - <rustc_ast_passes[ccae167a3a40ca07]::node_count::NodeCounter as rustc_ast[f496af66d74beb8c]::visit::Visitor>::visit_attribute
  15:     0x7ffe8f5a54fb - rustc_driver[9e128b4dc2b1f3f4]::main
  16:     0x7ff7e017100e - <unknown>
  17:     0x7ff7e0171076 - <unknown>
  18:     0x7ff7e017105c - <unknown>
  19:     0x7ffecbc8c0b1 - std::rt::lang_start_internal::h562b7c63b69fd4a3
  20:     0x7ff7e0171037 - <unknown>
  21:     0x7ff7e0171284 - <unknown>
  22:     0x7fff0f1b54e0 - BaseThreadInitThunk
  23:     0x7fff1130485b - RtlUserThreadStart

@CAD97 CAD97 added C-bug Category: This is a bug. I-ICE Issue: The compiler panicked, giving an Internal Compilation Error (ICE) ❄️ T-compiler Relevant to the compiler team, which will review and decide on the PR/issue. labels Jun 30, 2022
@CAD97
Copy link
Contributor Author

CAD97 commented Jun 30, 2022

@rustbot label +O-Windows

@rustbot rustbot added the O-windows Operating system: Windows label Jun 30, 2022
@ChrisDenton
Copy link
Member

This is a consequence of using the print series of macros. They ignore ERROR_INVALID_HANDLE errors but otherwise they're designed to panic on I/O errors.

The panic could be handled in a global catch_unwind. Or by using writeln! and handling the error in place.

@CAD97
Copy link
Contributor Author

CAD97 commented Jun 30, 2022

rustc explicitly chooses to override the startup code (which installs a SIGPIPE handler of SIG_IGN) and reinstall a handler of SIG_DFL:

#[cfg(unix)]
pub fn set_sigpipe_handler() {
unsafe {
// Set the SIGPIPE signal handler, so that an EPIPE
// will cause rustc to terminate, as expected.
assert_ne!(libc::signal(libc::SIGPIPE, libc::SIG_DFL), libc::SIG_ERR);
}
}

This means that rustc halts via SIGPIPE on POSIXy platforms and a broken pipe. To match this behavior on non-POSIX platforms, rustc should probably avoid the [e]print[ln]! family of macros, and use a custom version which process::exits on io::ErrorKind::BrokenPipe.

What makes this interesting to me is that rustc --help does terminate quietly on Windows in the face of a broken pipe; it's only -C help style help printing which ICEs.

The Zulip thread about the SIGPIPE situation is highly relevant here. The current PR provides a platform-specific #[unix_sigpipe] (a la #[windows_subsystem]) to choose the SIGPIPE behavior between inherit/SIG_DFL/SIG_IGN.

@ChrisDenton
Copy link
Member

What makes this interesting to me is that rustc --help does terminate quietly on Windows in the face of a broken pipe; it's only -C help style help printing which ICEs.

Oh, that is interesting and a bit of an odd difference. Should be easily fixed though? I mean if rustc already has code to print without ICEs.

@CAD97
Copy link
Contributor Author

CAD97 commented Jun 30, 2022

What makes this interesting to me is that rustc --help does terminate quietly on Windows in the face of a broken pipe; it's only -C help style help printing which ICEs.

--help

if matches.opt_present("h") || matches.opt_present("help") {
// Only show unstable options in --help if we accept unstable options.
let unstable_enabled = nightly_options::is_unstable_enabled(&matches);
let nightly_build = nightly_options::match_is_nightly_build(&matches);
usage(matches.opt_present("verbose"), unstable_enabled, nightly_build);
return None;
}

fn usage(verbose: bool, include_unstable_options: bool, nightly_build: bool) {
let groups = if verbose { config::rustc_optgroups() } else { config::rustc_short_optgroups() };
let mut options = getopts::Options::new();
for option in groups.iter().filter(|x| include_unstable_options || x.is_stable()) {
(option.apply)(&mut options);
}
let message = "Usage: rustc [OPTIONS] INPUT";
let nightly_help = if nightly_build {
"\n -Z help Print unstable compiler options"
} else {
""
};
let verbose_help = if verbose {
""
} else {
"\n --help -v Print the full set of options rustc accepts"
};
let at_path = if verbose {
" @path Read newline separated options from `path`\n"
} else {
""
};
println!(
"{options}{at_path}\nAdditional help:
-C help Print codegen options
-W help \
Print 'lint' options and default settings{nightly}{verbose}\n",
options = options.usage(message),
at_path = at_path,
nightly = nightly_help,
verbose = verbose_help
);
}

https://github.com/rust-lang/getopts/blob/c11eb65097d0dc9fe9ceb351d63c3ac8b5f05e0b/src/lib.rs#L586-L594

-C help

let cg_flags = matches.opt_strs("C");
if cg_flags.iter().any(|x| *x == "help") {
describe_codegen_flags();
return None;
}

println!("\nAvailable codegen options:\n");
print_flag_list("-C", config::CG_OPTIONS);

pub fn print_flag_list<T>(
cmdline_opt: &str,
flag_list: &[(&'static str, T, &'static str, &'static str)],
) {
let max_len = flag_list.iter().map(|&(name, _, _, _)| name.chars().count()).max().unwrap_or(0);
for &(name, _, _, desc) in flag_list {
println!(
" {} {:>width$}=val -- {}",
cmdline_opt,
name.replace('_', "-"),
desc,
width = max_len
);
}
}

There's nothing different going on here; println! is used in both paths.

Instead, what I think is happening is buffering. I wrote a little test program:

fn main() {
    for i in 0.. {
        dbg!(i);
        println!("Hello, world!");
    }
}

And running it I get

(All runs here are done in the Windows Terminal terminal emulator with a shell of nushell, which as of 0.64.0 is using cmd to run non-builtin commands. I did a smaller number of tests directly in cmd when I realized that this may be impacting the results, and observed equivalent behavior.)

❯ cargo build --release; ^'D:\.rust\target\release\playground.exe' | cmd /c 'exit'
    Finished release [optimized] target(s) in 0.00s
[src\main.rs:3] i = 0
[src\main.rs:3] i = 1
[src\main.rs:3] i = 2
[src\main.rs:3] i = 3
[src\main.rs:3] i = 4
[src\main.rs:3] i = 5
[src\main.rs:3] i = 6
[src\main.rs:3] i = 7
[src\main.rs:3] i = 8
[src\main.rs:3] i = 9
[src\main.rs:3] i = 10
[src\main.rs:3] i = 11
[src\main.rs:3] i = 12
[src\main.rs:3] i = 13
[src\main.rs:3] i = 16
[src\main.rs:3] i = 17
thread 'main' panicked at 'failed printing to stdout: The pipe is being closed. (os error 232)', library\std\src\io\stdio.rs:1015:9
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

The number of dbg!s I get is variable, though: I've seen as low as i = 10 and as high as i = 19. (I even saw i = 26 with this-command-does-not-exist in nushell...)

Some other runs with interesting qualities
❯ cargo build --release; ^'D:\.rust\target\release\playground.exe' | cmd /c 'exit'
    Finished release [optimized] target(s) in 0.00s
[src\main.rs:3] i = 0
[src\main.rs:3] i = 1
[src\main.rs:3] i = 2
[src\main.rs:3] i = 3
[src\main.rs:3] i = 4
[src\main.rs:3] i = 5
[src\main.rs:3] i = 6
[src\main.rs:3] i = 7
[src\main.rs:3] i = 8
[src\main.rs:3] i = 9
[src\main.rs:3] i = 10
[src\main.rs:3] i = 11
[src\main.rs:3] i = 12
[src\main.rs:3] i = 13
[src\main.rs:3] i = 16
[src\main.rs:3] i = 17
thread 'main' panicked at 'failed printing to stdout: The pipe is being closed. (os error 232)', library\std\src\io\stdio.rs:1015:9
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
❯ ^'D:\.rust\target\release\playground.exe' | cmd /c 'exit'
[src\main.rs:3] i = 0
[src\main.rs:3] i = 1
[src\main.rs:3] i = 2
[src\main.rs:3] i = 3
[src\main.rs:3] i = 4
[src\main.rs:3] i = 5
[src\main.rs:3] i = 6
[src\main.rs:3] i = 7
[src\main.rs:3] i = 8
[src\main.rs:3] i = 9
[src\main.rs:3] i = 10
[src\main.rs:3] i = 11
[src\main.rs:3] i = 14
[src\main.rs:3] i = 15
[src\main.rs:3] i = 16
thread 'main' panicked at 'failed printing to stdout: The pipe is being closed. (os error 232)', library\std\src\io\stdio.rs:1015:9
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
❯ cargo build --release; ^'D:\.rust\target\release\playground.exe' | cmd /c 'exit'
    Finished release [optimized] target(s) in 0.00s
[src\main.rs:3] i = 0
[src\main.rs:3] i = 1
[src\main.rs:3] i = 2
[src\main.rs:3] i = 3
[src\main.rs:3] i = 4
[src\main.rs:3] i = 5
[src\main.rs:3] i = 6
[src\main.rs:3] i = 7
[src\main.rs:3] i = 8
[src\main.rs:3] i = 9
[src\main.rs:3] i = 10
[src\main.rs:3] i = 11
[src\main.rs:3] i = 12
[src\main.rs:3] i = 13
[src\main.rs:3] i = 16
[src\main.rs:3] i = 17
thread 'main' panicked at 'failed printing to stdout: The pipe is being closed. (os error 232)', library\std\src\io\stdio.rs:1015:9
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
❯ cargo build --release; ^'D:\.rust\target\release\playground.exe' | cmd /c 'exit'
    Finished release [optimized] target(s) in 0.00s
[src\main.rs:3] i = 0
[src\main.rs:3] i = 1
[src\main.rs:3] i = 2
[src\main.rs:3] i = 3
[src\main.rs:3] i = 4
[src\main.rs:3] i = 5
[src\main.rs:3] i = 6
[src\main.rs:3] i = 7
[src\main.rs:3] i = 8
[src\main.rs:3] i = 9
[src\main.rs:3] i = 10
[src\main.rs:3] i = 11
[src\main.rs:3] i = 12
[src\main.rs:3] i = 13
[src\main.rs:3] i = 14
[src\main.rs:3] i = 15
[src\main.rs:3] i = 18
thread 'main' panicked at 'failed printing to stdout: The pipe is being closed. (os error 232)', library\std\src\io\stdio.rs:1015:9
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
❯ cargo build --release; ^'D:\.rust\target\release\playground.exe' | cmd /c 'exit'
    Finished release [optimized] target(s) in 0.00s
[src\main.rs:3] i = 0
[src\main.rs:3] i = 1
[src\main.rs:3] i = 2
[src\main.rs:3] i = 3
[src\main.rs:3] i = 4
[src\main.rs:3] i = 5
[src\main.rs:3] i = 6
[src\main.rs:3] i = 7
[src\main.rs:3] i = 8
[src\main.rs:3] i = 9
[src\main.rs:3] i = 10
[src\main.rs:3] i = 11
                      [src\main.rs:3] i = 12
[src\main.rs:3] i = 13
[src\main.rs:3] i = 14
[src\main.rs:3] i = 15
[src\main.rs:3] i = 16
[src\main.rs:3] i = 17
[src\main.rs:3] i = 18
thread 'main' panicked at 'failed printing to stdout: The pipe is being closed. (os error 232)', library\std\src\io\stdio.rs:1015:9
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
❯ cargo build --release; ^'D:\.rust\target\release\playground.exe' | cmd /c 'exit'
    Finished release [optimized] target(s) in 0.00s
[src\main.rs:3] i = 0
[src\main.rs:3] i = 1
[src\main.rs:3] i = 2
[src\main.rs:3] i = 3
[src\main.rs:3] i = 4
[src\main.rs:3] i = 5
[src\main.rs:3] i = 6
[src\main.rs:3] i = 7
[src\main.rs:3] i = 8
[src\main.rs:3] i = 9
[src\main.rs:3] i = 10
[src\main.rs:3] i = 11
[src\main.rs:3] i = 12
[src\main.rs:3] i = 13
[src\main.rs:3] i = 14
[src\main.rs:3] i = 15
[src\main.rs:3] i = 16
[src\main.rs:3] i = 17
[src\main.rs:3] i = 19
thread 'main' panicked at 'failed printing to stdout: The pipe is being closed. (os error 232)', library\std\src\io\stdio.rs:1015:9
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

These commands were run directly into a cmd shell, still with Windows Terminal as the terminal emulator:

D:\git\cad97\playground>cargo build --release && "D:\.rust\target\release\playground.exe" | cmd /c "exit"
    Finished release [optimized] target(s) in 0.00s
[src\main.rs:3] i = 0
[src\main.rs:3] i = 1
[src\main.rs:3] i = 2
[src\main.rs:3] i = 3
[src\main.rs:3] i = 4
[src\main.rs:3] i = 5
[src\main.rs:3] i = 6
[src\main.rs:3] i = 7
                     [src\main.rs:3] i = 8
[src\main.rs:3] i = 9
[src\main.rs:3] i = 10
thread 'main' panicked at 'failed printing to stdout: The pipe is being closed. (os error 232)', library\std\src\io\stdio.rs:1015:9
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

D:\git\cad97\playground>cargo build --release && "D:\.rust\target\release\playground.exe" | cmd /c "exit"
    Finished release [optimized] target(s) in 0.00s
[src\main.rs:3] i = 0
[src\main.rs:3] i = 1
[src\main.rs:3] i = 2
[src\main.rs:3] i = 3
[src\main.rs:3] i = 4
[src\main.rs:3] i = 5
[src\main.rs:3] i = 6
[src\main.rs:3] i = 7
[src\main.rs:3] i = 8
                     [src\main.rs:3] i = 9
[src\main.rs:3] i = 10
[src\main.rs:3] i = 11
[src\main.rs:3] i = 12
thread 'main' panicked at 'failed printing to stdout: The pipe is being closed. (os error 232)', library\std\src\io\stdio.rs:1015:9
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

D:\git\cad97\playground>cargo build --release && "D:\.rust\target\release\playground.exe" | cmd /c "exit"
    Finished release [optimized] target(s) in 0.00s
[src\main.rs:3] i = 0
[src\main.rs:3] i = 1
[src\main.rs:3] i = 2
[src\main.rs:3] i = 3
[src\main.rs:3] i = 4
[src\main.rs:3] i = 5
[src\main.rs:3] i = 6
[src\main.rs:3] i = 7
[src\main.rs:3] i = 8
[src\main.rs:3] i = 9
                     [src\main.rs:3] i = 10
[src\main.rs:3] i = 11
[src\main.rs:3] i = 12
[src\main.rs:3] i = 13
[src\main.rs:3] i = 14
thread 'main' panicked at 'failed printing to stdout: The pipe is being closed. (os error 232)', library\std\src\io\stdio.rs:1015:9
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

In the limited trials I did, I didn't see any skipped iterations directly in cmd.

Something interesting is going on here: if you'll note, the highlighted example is missing i = 14 and i = 15, despite stderr locking saying that this shouldn't be possible. This isn't a one-off error or just copy/paste error, either; this kind of data loss happened multiple times (see above dropdown for some cherry-picked trial runs).

In any case, changing the loop to 0..10 results in a quiet exit every time. The reason rustc --help exits quietly thus seems to be not because that code path is handling ErrorKind::BrokenPipe, but because Windows isn't returning a broken pipe error quickly.

Now, I realized after collecting most of the above data that the shell may be impacting the result... Observed differences:

  • nushell turns ^'D:\.rust\target\release\playground.exe' | extern-command into roughly cmd /c "D:\.rust\target\release\playground.exe" | cmd /c extern-command. This is why ^'D:\.rust\target\release\playground.exe' | this-command-does-not-exist results in a broken pipe.
  • cmd and pwsh parse and do command lookup before executing the first part of a pipeline. This means e.g. &'D:\.rust\target\release\playground.exe' | this-command-does-not-existpwsh fails before calling playground.exe at all.
  • pwsh is really an odd one out here...
❯ cargo build --release; &'D:\.rust\target\release\playground.exe' | cmd /c 'exit'
   Compiling playground v0.1.0 (D:\git\cad97\playground)
    Finished release [optimized] target(s) in 0.46s
[src\main.rs:3] i = 0
[src\main.rs:3] i = 1
[src\main.rs:3] i = 2
[src\main.rs:3] i = 3
[src\main.rs:3] i = 4
[src\main.rs:3] i = 5
[src\main.rs:3] i = 6
[src\main.rs:3] i = 7
[src\main.rs:3] i = 8
[src\main.rs:3] i = 9
[src\main.rs:3] i = 10
[src\main.rs:3] i = 11
[src\main.rs:3] i = 12
[src\main.rs:3] i = 13
[src\main.rs:3] i = 14
[src\main.rs:3] i = 15
[src\main.rs:3] i = 16
[src\main.rs:3] i = 17
[src\main.rs:3] i = 18
[src\main.rs:3] i = 19
[src\main.rs:3] i = 20
[src\main.rs:3] i = 21
[src\main.rs:3] i = 22
[src\main.rs:3] i = 23
[src\main.rs:3] i = 24

(this continues infinitely.)

Eerily, it seems that pwsh treats a pipe-to-finished-program as an infinite sink, not a broken pipe! This means that in pwsh, &"D:\.rust\target\release\playground.exe" | more and inputting q will hang until you CTRL-C the pipeline. In cmd, nushell-on-cmd, and Git Bash

For completeness sake, under Git Bash (a MINGW64), "D:\.rust\target\release\playground.exe" | sh -c 'exit' consistently gives fatal runtime error: I/O error: operation failed to complete synchronously. Additionally, under all tested shells (Git Bash, pwsh, cmd, nushell-on-cmd), doing the equivalent of > /dev/null and CTRL-Cing the pipeline exited without a panic, as did the equivalent of | more > /dev/null1. (As opposed to on a properly POSIX shell with SIGPIPE, where AIUI non-final entries in the pipeline get SIGPIPE and continue running if they SIG_IGN it, rather than receiving SIGINT? Leading to panics?)

Footnotes

  1. New info! Most of the time "D:\.rust\target\release\playground.exe" | less > /dev/null in Git Bash hangs until CTRL-C exits without a panic. (q is not accepted by this pipeline.) But sometimes when I've just run with | sh -c 'exit' piping to less (with or without > /dev/null) will result in fatal runtime error: I/O error: operation failed to complete synchronously, and once I even just got fatal runtime error: with no more info. (I'm still running the same pc-windows-msvc build from MINGW.)

Dylan-DPC added a commit to Dylan-DPC/rust that referenced this issue Aug 9, 2022
Error on broken pipe but do not backtrace or ICE

Windows will report a broken pipe as a normal error which in turn `println!` will panic on. Currently this causes rustc to produce a backtrace and ICE. However, this is not a bug with rustc so a backtrace is overly verbose and ultimately unhelpful to the user.

Kind of fixes rust-lang#98700. Although this is admittedly a bit of a hack because at panic time all we have is a string to inspect. On zulip it was suggested that libstd might someday provide a way to indicate a soft panic but that day isn't today.
@bors bors closed this as completed in cf7a9ae Aug 10, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
C-bug Category: This is a bug. I-ICE Issue: The compiler panicked, giving an Internal Compilation Error (ICE) ❄️ O-windows Operating system: Windows T-compiler Relevant to the compiler team, which will review and decide on the PR/issue.
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants