Don't panic on broken pipes when built without termcolor

[oherrala]

Depending on if termcolor crate is used or not env_logger's behavior on closed stderr (or stdout) is different. When using termcolor and the output is closed the process just hangs. When not using termcolor a panic occurs because of broken pipe and process is terminated.

I'm not sure how this case should work. Hanging indefinitely is bad and might lead to hard to debug issues. But to panic without possibility to recover is also bad.

An example for reproducing and testing (tested on macOS 11.6):

Cargo.toml:

[package]
name = "envltest"
version = "0.1.0"
edition = "2021"

[features]
termcolor = [ "env_logger/termcolor" ]

[dependencies]
env_logger = { version = "0.9", default_features = false }
log = "0.4"

main.rs:

fn main() {
    env_logger::builder()
        // This is to not hide error messages on stderr
        .target(env_logger::Target::Stdout)
        .init();

    for i in 0.. {
        log::info!("{}", i);
        std::thread::sleep(std::time::Duration::from_secs(1));
    }
}

When env_logger is build with no default features (as seen in Cargo.toml) the process is terminated as soon as stdout is closed (head -n3 takes three lines and closes stdout):

% cargo build && RUST_LOG=info /tmp/rust/target/debug/envltest | head -n3                     
    Finished dev [unoptimized + debuginfo] target(s) in 0.02s
[INFO  envltest] 0
[INFO  envltest] 1
[INFO  envltest] 2
thread 'main' panicked at 'failed printing to stdout: Broken pipe (os error 32)', library/std/src/io/stdio.rs:1193:9
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

however, when compiled with termcolor crate the process just hangs until the process is terminated manually:

% cargo build --features termcolor && RUST_LOG=info /tmp/rust/target/debug/envltest | head -n3
    Finished dev [unoptimized + debuginfo] target(s) in 0.02s
[INFO  envltest] 0
[INFO  envltest] 1
[INFO  envltest] 2
^C

Backtrace of broken pipe:

thread 'main' panicked at 'failed printing to stdout: Broken pipe (os error 32)', library/std/src/io/stdio.rs:1193:9
stack backtrace:
   0: rust_begin_unwind
             at /rustc/09c42c45858d5f3aedfa670698275303a3d19afa/library/std/src/panicking.rs:517:5
   1: std::panicking::begin_panic_fmt
             at /rustc/09c42c45858d5f3aedfa670698275303a3d19afa/library/std/src/panicking.rs:460:5
   2: std::io::stdio::print_to
             at /rustc/09c42c45858d5f3aedfa670698275303a3d19afa/library/std/src/io/stdio.rs:1193:9
   3: std::io::stdio::_print
             at /rustc/09c42c45858d5f3aedfa670698275303a3d19afa/library/std/src/io/stdio.rs:1205:5
   4: env_logger::fmt::writer::termcolor::imp::BufferWriter::print
             at /Users/oherrala/.cargo/registry/src/github.com-1ecc6299db9ec823/env_logger-0.9.0/src/fmt/writer/termcolor/shim_impl.rs:47:39
   5: env_logger::fmt::writer::Writer::print
             at /Users/oherrala/.cargo/registry/src/github.com-1ecc6299db9ec823/env_logger-0.9.0/src/fmt/writer/mod.rs:120:9
   6: env_logger::fmt::Formatter::print
             at /Users/oherrala/.cargo/registry/src/github.com-1ecc6299db9ec823/env_logger-0.9.0/src/fmt/mod.rs:115:9
   7: <env_logger::Logger as log::Log>::log::{{closure}}::{{closure}}
             at /Users/oherrala/.cargo/registry/src/github.com-1ecc6299db9ec823/env_logger-0.9.0/src/lib.rs:928:67
   8: core::result::Result<T,E>::and_then
             at /rustc/09c42c45858d5f3aedfa670698275303a3d19afa/library/core/src/result.rs:966:22
   9: <env_logger::Logger as log::Log>::log::{{closure}}
             at /Users/oherrala/.cargo/registry/src/github.com-1ecc6299db9ec823/env_logger-0.9.0/src/lib.rs:928:21
  10: <env_logger::Logger as log::Log>::log::{{closure}}
             at /Users/oherrala/.cargo/registry/src/github.com-1ecc6299db9ec823/env_logger-0.9.0/src/lib.rs:947:33
  11: std::thread::local::LocalKey<T>::try_with
             at /rustc/09c42c45858d5f3aedfa670698275303a3d19afa/library/std/src/thread/local.rs:399:16
  12: <env_logger::Logger as log::Log>::log
             at /Users/oherrala/.cargo/registry/src/github.com-1ecc6299db9ec823/env_logger-0.9.0/src/lib.rs:934:27
  13: log::__private_api_log
             at /Users/oherrala/.cargo/registry/src/github.com-1ecc6299db9ec823/log-0.4.14/src/lib.rs:1460:5
  14: envltest::main
             at ./src/main.rs:7:9
  15: core::ops::function::FnOnce::call_once
             at /rustc/09c42c45858d5f3aedfa670698275303a3d19afa/library/core/src/ops/function.rs:227:5

[oherrala]

My original issue had wrong assumption. The process doesn't hang, but keeps going in case when using termcolor:

use std::io::Write;

fn main() {
    env_logger::builder()
        .target(env_logger::Target::Stdout)
        .init();

    for i in 0.. {
        log::info!("{}", i);
        std::thread::sleep(std::time::Duration::from_secs(1));
        std::io::stderr().write(b"hello\n").unwrap();
    }
}

this continues to print hello after stdout is closed so the process continues to run but log output is just lost:

% cargo build --features termcolor && RUST_LOG=info /tmp/rust/target/debug/envltest | head -n3
   Compiling envltest v0.1.0 (/Users/oherrala/tmp/envltest)
    Finished dev [unoptimized + debuginfo] target(s) in 1.15s
[INFO  envltest] 0
hello
[INFO  envltest] 1
hello
[INFO  envltest] 2
hello
hello
hello
hello
^C

[epage]

Could you clarify what you feel the expected behavior would be? Generally, logging is a never-fail operation, so I can't really see that env_logger can do anything else when its output pipe is closed.

[oherrala]

@epage I expect the behavior to be the same in the two scenarios (with and without termcolor crate). So either panic or continue going. This difference of behavior was IIRC quite challenging to debug when we encountered this issue.

[epage]

Ah, I had missed that you were contrasting behavior without that feature. I would describe the panic as a bug and renamed the issue accordingly.

[epage]

Hmm, this was broken in #82 with the explanation

        // This impl uses the `eprint` and `print` macros
        // instead of using the streams directly.
        // This is so their output can be captured by `cargo test`

I wonder what those macros do differently with tests.

[epage]

Also, note when fixing this, we also use print and eprint in termcolor in some cases