Broken pipe if stdout is piped to head utility

[petr-fischer]

Code to reproduce:

1.to 1000 { |i| puts "123456789012345678901234567890123456789012345678901234567890 #{i}" }

Then, when I try to pipe with command:

crystal src/head_io_bug.cr | head

This error output occurs:

123456789012345678901234567890123456789012345678901234567890 1
123456789012345678901234567890123456789012345678901234567890 2
123456789012345678901234567890123456789012345678901234567890 3
123456789012345678901234567890123456789012345678901234567890 4
123456789012345678901234567890123456789012345678901234567890 5
123456789012345678901234567890123456789012345678901234567890 6
123456789012345678901234567890123456789012345678901234567890 7
123456789012345678901234567890123456789012345678901234567890 8
123456789012345678901234567890123456789012345678901234567890 9
123456789012345678901234567890123456789012345678901234567890 10
Unhandled exception: Error writing file: Broken pipe (Errno)
  from /usr/local/lib/crystal/crystal/system/unix/file_descriptor.cr:79:13 in 'unbuffered_write'
  from /usr/local/lib/crystal/io/buffered.cr:179:5 in 'flush'
  from /usr/local/lib/crystal/io/buffered.cr:131:7 in 'write'
  from /usr/local/lib/crystal/io.cr:481:7 in 'write_utf8'
  from /usr/local/lib/crystal/string.cr:4254:5 in 'to_s'
  from /usr/local/lib/crystal/io.cr:184:5 in '<<'
  from /usr/local/lib/crystal/io.cr:227:5 in 'puts'
  from /usr/local/lib/crystal/kernel.cr:366:3 in 'puts'
  from /usr/local/lib/crystal/int.cr:410:7 in '__crystal_main'
  from /usr/local/lib/crystal/crystal/main.cr:97:5 in 'main_user_code'
  from /usr/local/lib/crystal/crystal/main.cr:86:7 in 'main'
  from /usr/local/lib/crystal/crystal/main.cr:106:3 in 'main'
  from _start
  from ???
Failed to raise an exception: 7431104
[0x449bd6] *CallStack::print_backtrace:Int32 +118
[0x430456] __crystal_raise +86
[0x466c74] *IO::FileDescriptor +260
[0x466b03] *IO::FileDescriptor +83
[0x489d6c] *Crystal::main<Int32, Pointer(Pointer(UInt8))>:Int32 +156
[0x43ab36] main +6
[0x42f7e5] _start +149
[0x8006be000] ???

version:

Crystal 0.28.0 (2019-04-18)

LLVM: 6.0.1
Default target: x86_64-portbld-freebsd11.2
(broken also on Linux/Ubuntu Linux, same behaviour)

[petr-fischer]

Interesting is, that this code:

1.to 1000 { |i| puts "1234567890 #{i}" }

With same pipe command:

crystal src/head_io_bug.cr | head

Generates different error ouput:

1234567890 1
1234567890 2
1234567890 3
1234567890 4
1234567890 5
1234567890 6
1234567890 7
1234567890 8
1234567890 9
1234567890 10
Failed to raise an exception: 7434048
[0x449bc6] *CallStack::print_backtrace:Int32 +118
[0x430446] __crystal_raise +86
[0x466c64] *IO::FileDescriptor +260
[0x466af3] *IO::FileDescriptor +83
[0x489d5c] *Crystal::main<Int32, Pointer(Pointer(UInt8))>:Int32 +156
[0x43ab26] main +6
[0x42f7e5] _start +149
[0x8006be000] ???

[asterite]

Does it happen if you compile the program and then run it?

crystal build src/head_io_bug.cr 
./head_io_bug | head

If not, it means it's just a compiler issue, maybe because the program is run inside the compiler run or something.

[petr-fischer]

@asterite Yes, the situation is the same after "crystal build" or "shards build" (also with --release or --static)

[asterite]

The same? Strange. For me it works fine when I compile it separately.

What's your crystal version?

[asterite]

And platform.

[petr-fischer]

@asterite Can you try even longer test string?

Crystal 0.28.0 (2019-04-18)

LLVM: 6.0.1
Default target: x86_64-portbld-freebsd11.2

[daliborfilus]

Using code snippet above:

1.to 1000 { |i| puts "1234567890 #{i}" }

$ uname -a
Linux hostname 4.15.0-48-generic #51-Ubuntu SMP Wed Apr 3 08:28:49 UTC 2019 x86_64 x86_64 x86_64 GNU/Linux

$ crystal build head_io_bug.cr 
$ ./head_io_bug |head
1234567890 1
1234567890 2
1234567890 3
1234567890 4
1234567890 5
1234567890 6
1234567890 7
1234567890 8
1234567890 9
1234567890 10
Failed to raise an exception: END_OF_STACK
[0x55cabd5ca486] *CallStack::print_backtrace:Int32 +118
[0x55cabd5b0b26] __crystal_raise +86
[0x55cabd5e1c74] *IO::FileDescriptor +260
[0x55cabd5e1b03] *IO::FileDescriptor +83
[0x55cabd60ac4c] *Crystal::main<Int32, Pointer(Pointer(UInt8))>:Int32 +156
[0x55cabd5bb216] main +6
[0x7f912be60b97] __libc_start_main +231
[0x55cabd5affca] _start +42
[0x0] ???

[daliborfilus]

This seems to be even more occuring when using Logger class:

$ uname -a
Linux hostname 4.15.0-48-generic #51-Ubuntu SMP Wed Apr 3 08:28:49 UTC 2019 x86_64 x86_64 x86_64 GNU/Linux

$ crystal -v
Crystal 0.28.0 [639e4765f] (2019-04-17)

LLVM: 4.0.0
Default target: x86_64-unknown-linux-gnu

$ crystal init app issue7810
$ editor src/issue7810.cr

require "logger"
logger = Logger.new(STDOUT)
(1..100).each { |i| logger.info "logged line #{i}" }

$ shards build
Dependencies are satisfied
Building: issue7810
$  ./bin/issue7810 | head
I, [2019-05-22 15:43:48 +02:00 #15646]  INFO -- : logged line 1
I, [2019-05-22 15:43:48 +02:00 #15646]  INFO -- : logged line 2
I, [2019-05-22 15:43:48 +02:00 #15646]  INFO -- : logged line 3
I, [2019-05-22 15:43:48 +02:00 #15646]  INFO -- : logged line 4
I, [2019-05-22 15:43:48 +02:00 #15646]  INFO -- : logged line 5
I, [2019-05-22 15:43:48 +02:00 #15646]  INFO -- : logged line 6
I, [2019-05-22 15:43:48 +02:00 #15646]  INFO -- : logged line 7
I, [2019-05-22 15:43:48 +02:00 #15646]  INFO -- : logged line 8
I, [2019-05-22 15:43:48 +02:00 #15646]  INFO -- : logged line 9
I, [2019-05-22 15:43:48 +02:00 #15646]  INFO -- : logged line 10
Unhandled exception: Error writing file: Broken pipe (Errno)
  from /usr/share/crystal/src/crystal/system/unix/file_descriptor.cr:79:13 in 'unbuffered_write'
  from /usr/share/crystal/src/io/buffered.cr:179:5 in 'flush'
  from /usr/share/crystal/src/logger.cr:175:7 in 'write'
  from /usr/share/crystal/src/logger.cr:155:5 in 'log'
  from /usr/share/crystal/src/logger.cr:129:3 in 'info'
  from /usr/share/crystal/src/logger.cr:129:3 in 'info'
  from src/issue7810.cr:3:21 in '__crystal_main'
  from /usr/share/crystal/src/crystal/main.cr:97:5 in 'main_user_code'
  from /usr/share/crystal/src/crystal/main.cr:86:7 in 'main'
  from /usr/share/crystal/src/crystal/main.cr:106:3 in 'main'
  from __libc_start_main
  from _start
  from ???
Failed to raise an exception: END_OF_STACK
[0x557c1f86a216] *CallStack::print_backtrace:Int32 +118
[0x557c1f84e376] __crystal_raise +86
[0x557c1f8895c4] *IO::FileDescriptor +260
[0x557c1f889453] *IO::FileDescriptor +83
[0x557c1f8c746c] *Crystal::main<Int32, Pointer(Pointer(UInt8))>:Int32 +156
[0x557c1f858a66] main +6
[0x7fa3a5a14b97] __libc_start_main +231
[0x557c1f84d70a] _start +42
[0x0] ???

[asterite]

Oh, yes, I was able to reproduce it. The first time it worked well for some reason...

This is a revival of #2713

[NIFR91]

Can reproduce the error

Crystal 0.31.1 [0e2e1d067] (2019-09-30)

LLVM: 8.0.0
Default target: x86_64-unknown-linux-gnu

[ysbaddaden]

The problem is that head closes it's STDIN once it has read the first n lines, but the crystal program continues to write to it's STDOUT which results into an EPIPE exception —the other end of the pipe is closed.

This doesn't happen with tail, because tail will read everything from its STDIN then print the last n lines.

I don't know how other languages deal with this.

[rdp]

Ruby spits out a backtrace like this, as well. Is there any way to modify the current behavior (outputting the main thread's trace to STDERR before exiting)?