getting Broken pipe on `--enable-debug --disable-optimize` build

[pnkfelix]

After the following IRC conversation: https://botbot.me/mozilla/rust/msg/13926593/

I made the following test case:

fn main() {
    let mut inp = std::io::stdin();
    println!("{}", inp.read_line());
    for _ in range(0, 100) {
        std::io::println("b")
    }
}

(The blocking read at the beginning was to offer me the opportunity to attach a debugger.)

I have two builds of rustc. One is build with --enable-debug --enable-optimize; the other with --enable-debug --disable-optimize. The latter build is nondeterministically getting a pipe broken error when piping the above program into head:

% grep CFG_CONFIGURE_ARGS ~/Dev/Mozilla/rust.git/objdir-dbgopt/config.mk 
CFG_CONFIGURE_ARGS   := --enable-debug --enable-optimize --enable-ccache --enable-clang --prefix=~/opt/rust-dbg
% grep CFG_CONFIGURE_ARGS ~/Dev/Mozilla/rust.git/objdir-dbg/config.mk 
CFG_CONFIGURE_ARGS   := --enable-debug --disable-optimize --enable-ccache --enable-clang --prefix=~/opt/rust-dbg-nopt
% ~/Dev/Mozilla/rust.git/objdir-dbgopt/x86_64-apple-darwin/stage2/bin/rustc --version
/Users/fklock/Dev/Mozilla/rust.git/objdir-dbgopt/x86_64-apple-darwin/stage2/bin/rustc 0.11-pre (7a19a82 2014-04-27 23:06:41 -0700)
host: x86_64-apple-darwin
% ~/Dev/Mozilla/rust.git/objdir-dbg/x86_64-apple-darwin/stage2/bin/rustc --version
/Users/fklock/Dev/Mozilla/rust.git/objdir-dbg/x86_64-apple-darwin/stage2/bin/rustc 0.11-pre (7a19a82 2014-04-27 23:06:41 -0700)
host: x86_64-apple-darwin
% ~/Dev/Mozilla/rust.git/objdir-dbgopt/x86_64-apple-darwin/stage2/bin/rustc /tmp/nums.rs 
% echo a | ./nums | head
Ok(a
)
b
b
b
b
b
b
b
b
% ~/Dev/Mozilla/rust.git/objdir-dbg/x86_64-apple-darwin/stage2/bin/rustc /tmp/nums.rs 
% echo a | ./nums | head
Ok(a
)
b
b
b
b
b
b
b
b
% echo a | ./nums | head
Ok(a
)
b
b
b
b
b
b
b
b
task '<main>' failed at 'failed printing to stdout: broken pipe (Broken pipe)', /Users/fklock/Dev/Mozilla/rust.git/src/libstd/io/stdio.rs:245
% 

[pnkfelix]

(it is of course possible that both types of builds would exhibit the bug, and that the --disable-optimize is just increasing the probability of the failure by some large amount.)

[pnkfelix]

cc @alexcrichton

[alexcrichton]

This seems quite normal to me. You get a broken pipe when someone closes stdin (as head did after it finished reading), and I expect that --disable-optimize slowed everything down which caused everything to show up more. It could be the case that with the --enable-optimize build that it's fast enough to write everything before head closes stdin.

What is the behavior you expect to see here?

[pnkfelix]

@alexcrichton you are right, I should have said up front that I was not sure if this was a bug or not.

I suppose the real question then is: How should someone who wants to write code that will interact with Unix tools like head handle this case properly?

• Should they not use println!? (i.e. Should we make a variant of println! that returns Result?)
• Should they put their code into a separate task and then fire that off from a monitoring task to catch the failure?

Or should we change/extend our IO library to ease this use case?

[alexcrichton]

I would expect any user wanting to handle errors printing to stdout to use io::stdout() rather than println!. I don't think we really need to add another variant of println! because I imagine this will be fairly rare, and the separate task shouldn't be needed once you're using a real I/O object.

My guess is that we don't need to change the current state of affairs, except perhaps to ignore errors instead of failing on them.

[Morgawr]

Hey, I'm the guy who reported this "bug" on the irc.
I don't really know why this is happening (I can guess, it's not too hard), but I'd like to say that piping a process' output to other programs (that might or might not break those pipes as soon as they finish reading) is something very common on Unix systems (as you probably already know) and this behavior is a bit confusing and unexpected.
Regardless of whether or not this is considered a bug, I'd say the behavior should be changed in such a way that it doesn't cause problems or misunderstandings with Unix pipes.

[alexcrichton]

Do you have an idea of the behavior that you're expecting. What's happening is that you issued a println! when stdout was closed, returning a broken pipe. Do you think that the error should be ignored?

[Morgawr]

Unless Rust standard behavior is that I need to take some sort of lock around an stdout operation before issuing a print, I'd expect that the first process (the rust process) that pipes to head should not crash and error if some other process is trying to read from such shared pipe and then closes it.

I mean, maybe this is what happens on Unix pipes under the hood and I was never aware of it, but if I write the equivalent C program to print 100 numbers to stdout and pipe it to head, I'm expecting it not to crash halfway through.

[alexcrichton]

Rust is not crashing, it is triggering a task failure. When you write the equivalent C program the same thing is happening, but you are ignoring all of the errors (almost no one checks the return value of printf).

There's no need for any locking here, I'm curious if you think that rust should be ignoring the error on the write?

[Morgawr]

The standard behavior of printf is to return the number of written characters to stdout or a negative value in case of error. In case of piping an equivalent C program to head, none of the printf ever fail or return truncated values.

Actually, I just checked the differences in behavior for a Rust and a C equivalent program, by printing to both stdout (captured by head) and stderr. The substantial difference is that the C program always terminates, I get to see all 100 numbers printed to stderr and capture only the first 10 to stdout with head. In Rust, instead, the numbers are printed one by one and captured by head, until head decides to cut off the pipe and then the Rust program stops (crashes? exits? throws an exception? Irrelevant).

Expected behavior when running a piped program: the program runs to completion as if it were running without any pipe at all.
Current rust behavior: the program behaves differently with or without a pipe, and sometimes this broken pipe makes the program close prematurely.

This difference has the potential of breaking the expected behavior in automated scripts for a lot of system administration's tools and setups. Imagine if my program is supposed to perform some important action and I want to pipe it to another program that only gets so much data and then closes the pipe, the first program would potentially crash and work incorrectly.

[alexcrichton]

In case of piping an equivalent C program to head, none of the printf ever fail or return truncated values.

This is not true. When printing to a pipe, printf is by default buffered by something around 4k. This means that your program is likely only issuing one write syscall, which will always succeed (head is reading at least something).

If you turn off buffering, the program dies with a SIGPIPE:

$ strace ./foo | head -n 3
execve("./foo", ["./foo"], [/* 26 vars */]) = 0
brk(0)                                  = 0x228a000
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f6572c6b000
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=92196, ...}) = 0
mmap(NULL, 92196, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f6572c54000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\360\36\2\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=1853400, ...}) = 0
mmap(NULL, 3961912, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f6572683000
mprotect(0x7f6572840000, 2097152, PROT_NONE) = 0
mmap(0x7f6572a40000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1bd000) = 0x7f6572a40000
mmap(0x7f6572a46000, 17464, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f6572a46000
close(3)                                = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f6572c53000
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f6572c51000
arch_prctl(ARCH_SET_FS, 0x7f6572c51740) = 0
mprotect(0x7f6572a40000, 16384, PROT_READ) = 0
mprotect(0x600000, 4096, PROT_READ)     = 0
mprotect(0x7f6572c6d000, 4096, PROT_READ) = 0
munmap(0x7f6572c54000, 92196)           = 0
fstat(1, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f6572c6a000
write(1, "test\n", 5)                   = 5
write(1, "test\n", 5test
test
)                   = 5
write(1, "test\n", 5test
)                   = 5
write(1, "test\n", 5)                   = -1 EPIPE (Broken pipe)
--- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=24113, si_uid=1000} ---
+++ killed by SIGPIPE +++

This means to emulate the same behavior, the rust program should abort() on SIGPIPE. This is unsafe, so it is contained as part of a task failure (explaining the current semantics).

I don't quite understand how the runtime would sanely change to support this use case. This seems to be acting precisely as what C does, except in a more controlled manner. If you are expecting a particular amount of buffering, then it is expected that you manually provide such buffering (via stdio::set_stdout).

[Morgawr]

I see, however this is not the same behavior I am getting on printf(). Maybe glibc or the environment overrides normal settings but even when I run:
setvbuf(stdout, NULL, _IONBF, 0);
setvbuf(stderr, NULL, _IONBF, 0);
in a C program, it still runs until completion when piped to head. When I run it with strace, however, it doesn't.

This is an interesting problem in my opinion, I have no idea what's the expected behavior anymore, really. Maybe somebody who knows more than me about this issue could comment on standard behaviors...

[alexcrichton]

The behavior you're seeing on unix is likely one of two situations:

1. All data is written before the pipe is terminated. This is always a possibility (head and your program could be running in parallel). This could also be a result of buffered writes at some layer of the stack (perhaps the kernel could be buffering, or even head itself?)
2. A write is returning error, but the error is EPIPE. The C runtime by default sends SIGPIPE to a program that would otherwise receive EPIPE. Your program likely doesn't have a SIGPIPE handler, so it is terminated.

If the rust program falls into bucket 1, then there's no difference. The difference between rust and C in bucket 2 is that rust is a safe language, so it doesn't ever abort() by default. Rust ignores SIGPIPE by default, and will trigger a task failure rather than an abort().

In order to change semantics, rust would have to behave differently when it receives EPIPE, but I'm not fully convinced that it should change to something like abort(), and a task failure seems like the genuinely correct thing to do in this case.