-
-
Notifications
You must be signed in to change notification settings - Fork 1.6k
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
Broken pipe if stdout is piped to head utility #7810
Comments
Interesting is, that this code:
With same pipe command:
Generates different error ouput:
|
Does it happen if you compile the program and then run it?
If not, it means it's just a compiler issue, maybe because the program is run inside the compiler run or something. |
@asterite Yes, the situation is the same after "crystal build" or "shards build" (also with --release or --static) |
The same? Strange. For me it works fine when I compile it separately. What's your crystal version? |
And platform. |
@asterite Can you try even longer test string?
|
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] ??? |
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] ??? |
Oh, yes, I was able to reproduce it. The first time it worked well for some reason... This is a revival of #2713 |
Can reproduce the error Crystal 0.31.1 [0e2e1d067] (2019-09-30)
LLVM: 8.0.0
Default target: x86_64-unknown-linux-gnu |
The problem is that This doesn't happen with I don't know how other languages deal with this. |
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)? |
The issue is a more widespread than
|
I have found this issue for Rust. It's fair to raise when an application can't write to the stdout, which are often run as a daemon through a system service/containers. However, for CLI apps, they are usually used in a TTY terminal, there is no stdout writing problem. I think broken pipes for |
All languages just raise. As per the Rust issue, I believe each program is responsible to handle EPIPE on STDOUT as it see fits (crash with backtracenon STDERR/rescue and exit silently). I.e. this issue isn't a bug. I don't think ignoring EPIPE is a good idea. |
Yes right for the TTY, piping a command on a TTY run it as non-tty. |
I could see maybe a compiler directive to "not output any stacktraces to stderr" but...I guess the developer can just override it anyway (I forget how though)? |
@rdb use |
Some solutions:
In addition, maybe we could add a SILENT mode to Logger, and add a configuration to Logger to change the level to SILENT automatically on broken pipe (and keep raising by default)? It may be useful? I think it's better to have means to disable writing after EPIPE (if it's acceptable for the program) than ignoring EPIPE. |
Or override Callstack.print_frame
https://forum.crystal-lang.org/t/better-runtime-backtraces/1394/2?u=rogerdpack
but also nice might be some parameter "silence those uncaught exceptions"
or handle them instead of outputting to stderr or something like that :)
…On Sat, Dec 28, 2019 at 8:19 AM Julien Portalier ***@***.***> wrote:
Some solutions:
-
The old C way: Signal::PIPE.trap { exit } but this will cause EPIPE to
never be raised (for any file descriptor or socket), so it may be only
useful for single-thread single-fiber behavior. I.e. tiny utilities.
-
Wrap your main program, which will catch any other unrescued EPIPE
(not just STDOUT):
begin
# ...rescue ex : Errno
if ex.errno == Errno::EPIPE
exit
else
raise ex
endend
-
Wrap individual calls to STDOUT.write in the same begin/rescue as
above, which may be more tedious.
In addition, maybe we could add a SILENT mode to Logger, and add a
configuration to Logger to change the level to SILENT automatically on
broken pipe (and keep raising by default)? It may be useful?
I think it's better to have means to disable writing after EPIPE (if it's
acceptable for the program) than ignoring EPIPE.
—
You are receiving this because you commented.
Reply to this email directly, view it on GitHub
<#7810?email_source=notifications&email_token=AAADBUENOBLUI6GQRUAM4ADQ25VANA5CNFSM4HOUCE42YY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEHYL33I#issuecomment-569425389>,
or unsubscribe
<https://github.com/notifications/unsubscribe-auth/AAADBUHT3DSQCOU7ZLXF36DQ25VANANCNFSM4HOUCE4Q>
.
|
Setting crystal to exit on |
The pipes only take STDOUT to put in STDIN, STDERR is printed in the terminal. It would be a bit simpler when Errno error handling (#8305) will be improved. Should it be a toggle feature, like For reminding, we only want to exit on STDOUT broken pipe, nothing else. |
Ruby has no such configurations and it works fine all the time. Can't we do the same? Probably Go does it too, etc. |
Please, let's start with asking Why?, followed with Could we do it better? instead of blindly copying behaviors from others. btw, re: |
You might not even need `exit_on_broken_pipe` option maybe just "don't
output any uncaught stacktraces" option for the whole program [?] :)
…On Sun, Dec 29, 2019 at 8:26 AM Sijawusz Pur Rahnama < ***@***.***> wrote:
Ruby has no such configurations and it works fine all the time. Can't we
do the same? Probably Go does it too, etc.
Please, let's start with asking *Why?*, followed with *Could we do it
better?* instead of blindly copying behaviors from others.
btw, re: works fine all the time - you sure about that?
—
You are receiving this because you commented.
Reply to this email directly, view it on GitHub
<#7810?email_source=notifications&email_token=AAADBUFBGUKFUUTW4AGXJC3Q3C6QRA5CNFSM4HOUCE42YY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEHZB3PQ#issuecomment-569515454>,
or unsubscribe
<https://github.com/notifications/unsubscribe-auth/AAADBUBKQM66MAAZMCNNNX3Q3C6QRANCNFSM4HOUCE4Q>
.
|
@rdp Certainly not. Exceptions need to be handled explicitly or else displayed to the user. A generic silencer is not an option. Broken pipes are an entirely different type of error than for example internally corrupted state. When he program just exits without any error message, you couldn't possibly know what's going on. I'd consider closing a pipe as a message from the program's environment that it won't read any of its output anymore (or write any input). Obviously, a pipe can also be broken for other reasons. STDOUT.on_closed do
exit
end This enables the developer to decide what happens when a pipe is closed. It might not always be to exit immediately, but run a specific cleanup first, or change the modus operandi and continue the program execution. |
FWIW this advice doesn't work for me. Below is my code snippet, but even with this I get the same stacktrace output as above. Is the begin
groups.each_value.flat_map { |g| g }.to_a.sort!.each do |group|
puts group
end
rescue e : Errno
# when quitting early when piping output to another command we get an EPIPE so ignore that
if e.errno == Errno::EPIPE
exit
else
raise e
end
end |
Actually, this might get fixed by #8728 specially since the output of #7810 (comment) seems to hit it. |
I just sent #8791 that avoids the duplicate backtraces when STDOUT is closed and also avoids exceptions when STDOUT or STDERR are invoked from at_exit handlers or calls to I think the original motivation for this issue is not actually a bug: the STDOUT can be actually being closed and it's correct for the IO operations to fail. In a near future we might have an easier way to handle those errors by having a specific exception. |
I just tried the original example and see the error still.
I'm also getting this same error on my production Lucky apps. I tried to upgrade to 0.34, but had to downgrade back to 0.33 because the app won't stay up. |
Adding to the conversation, C++ swallows this error. The following code #include <iostream>
int main() {
int i = 1;
while (true) {
std::cout << i << '\n';
i += 1;
}
} works fine when piped to head. So perhaps we just need to do likewise. begin
...
command.run
rescue ex : IO::Error
if ex.os_error == Errno::EPIPE
exit 0
else
raise ex
end
rescue ex
...
end |
I think this is incorrect behaviour; this article recently posted on Hackernews expresses the problem better than I could: https://blog.sunfishcode.online/bugs-in-hello-world/ I think a non-zero exit code is more appropriate. |
Okay, I found something... If you try this snippet in Ruby: # foo.rb
1.upto(1000) { |i| puts "123456789012345678901234567890123456789012345678901234567890 #{i}" } And run it like this:
it works fine, no exception. But if you do this, which is more or less the same: io = IO.new(1) # This is STDOUT
1.upto(1000) { |i| io.puts "123456789012345678901234567890123456789012345678901234567890 #{i}" } and run it in the same way, you get:
AHA! So it happens the same thing in Ruby, but not if you use top-level This is where STDOUT is declared: https://github.com/ruby/ruby/blob/82dea29073d50304b6029b15d07666994533d8d1/io.c#L14885 rb_define_global_const("STDOUT", rb_stdout); Here's where https://github.com/ruby/ruby/blob/82dea29073d50304b6029b15d07666994533d8d1/io.c#L14872 rb_stdout = rb_io_prep_stdout(); And here's the definition of https://github.com/ruby/ruby/blob/82dea29073d50304b6029b15d07666994533d8d1/io.c#L8905-L8909 VALUE
rb_io_prep_stdout(void)
{
return prep_stdio(stdout, FMODE_WRITABLE|FMODE_SIGNAL_ON_EPIPE, rb_cIO, "<STDOUT>");
} What's this #define fptr_signal_on_epipe(fptr) \
(((fptr)->mode & FMODE_SIGNAL_ON_EPIPE) != 0) And here's the code that handles exceptions when writing to an IO: https://github.com/ruby/ruby/blob/82dea29073d50304b6029b15d07666994533d8d1/io.c#L546-L561 NORETURN(static void raise_on_write(rb_io_t *fptr, int e, VALUE errinfo));
static void
raise_on_write(rb_io_t *fptr, int e, VALUE errinfo)
{
#if defined EPIPE
if (fptr_signal_on_epipe(fptr) && (e == EPIPE)) {
const VALUE sig =
# if defined SIGPIPE
INT2FIX(SIGPIPE) - INT2FIX(0) +
# endif
INT2FIX(0);
rb_ivar_set(errinfo, ruby_static_id_signo, sig);
}
#endif
rb_exc_raise(errinfo);
} So for STDOUT, if writing produces EPIPE, it seems it transforms that into a signal and produces that signal (not sure how gets that signal, I think it's the same program, but I couldn't reproduce this) I think we could more or less do the same thing: don't raise by default, but have a way to catch this error when it happens (in Ruby it's by trapping the EPIPE signal) Alternatively we could have a special handler for this instead of a signal. Or just completely ignore it for STDOUT. Not sure! |
Actually, looking the code closer, it seems that an exception is still raised even with if |
Wow, it seems they changed that pretty recently: |
Okay, I understand now. A But, in essence, Ruby seems to translate the broken pipe exception into a broken pipe signal for the current program. I think we should do the same! |
Nice! With @ggiraldez we discussed this today and found that trapping Signal::PIPE.trap do
exit
end
i = 0
while true
p i
i += 1
end Doesn't exit on a broken pipe, but if we jump Crystal handling of signals, it works: LibC.signal(LibC::SIGPIPE, ->(value : Int32) {
LibC.exit(0)
})
i = 0
while true
p i
i += 1
end Now it works. |
Cool! Just a note that I was taking about Ruby |
As to what to do in Crystal, I'd say we could simply rescue the exception for STDOUT. |
And what if you want to handle that exception? |
Maybe add a compile time setting (env. variable?) something like "swallow
stdin/stdout failures" ?
…On Fri, Mar 11, 2022 at 6:45 AM Ary Borenszweig ***@***.***> wrote:
And what if you want to handle that exception?
—
Reply to this email directly, view it on GitHub
<#7810 (comment)>,
or unsubscribe
<https://github.com/notifications/unsubscribe-auth/AAADBUGCF6LECXUMRH6JXD3U7NE6BANCNFSM4HOUCE4Q>
.
Triage notifications on the go with GitHub Mobile for iOS
<https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675>
or Android
<https://play.google.com/store/apps/details?id=com.github.android&referrer=utm_campaign%3Dnotification-email%26utm_medium%3Demail%26utm_source%3Dgithub>.
You are receiving this because you were mentioned.Message ID:
***@***.***>
|
Wouldn't it be better to have a runtime global variable for this (set it at runtime using the API) rather than an ENV variable? |
IMO neither of these makes sense, you'd rather want to control this behavior on the callsite, rather than per-app. |
Go handles this problem like this: https://pkg.go.dev/os/signal#hdr-SIGPIPE This looks like a decent enough default behaviour. |
I noticed a difference in this behavior today. Rubyruby -e "loop do puts :ruby end" | head -n 3 ruby
ruby
ruby
Crystalcrystal eval "loop do puts :crys end" | head -n 3 crys
crys
crys
Unhandled exception: Error writing file: Broken pipe (IO::Error)
from /opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/io/evented.cr:82:13 in 'unbuffered_write'
from /opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/io/buffered.cr:239:5 in 'flush'
from /opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/io/buffered.cr:178:7 in 'write_byte'
from /opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/char.cr:983:9 in 'to_s'
from /opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/io.cr:177:5 in '<<'
from /opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/io.cr:191:5 in 'print'
from /opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/io.cr:246:5 in 'puts'
from /opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/io.cr:235:5 in 'puts'
from /opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/kernel.cr:418:3 in 'puts'
from eval:1:9 in '__crystal_main'
from /opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/crystal/main.cr:129:5 in 'main_user_code'
from /opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/crystal/main.cr:115:7 in 'main'
from /opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/crystal/main.cr:141:3 in 'main' I think Ruby is better on this. |
It's also worth noting that this issue is also present on Windows, although probably not as common. Windows doesn't have a native puts [gets, gets, gets].join '\n' Running
Doing hello
hello
hello
Unhandled exception: Error writing file: Invalid argument (IO::Error)
from C:\Users\user\AppData\Roaming\crimson\crystal\1.9.2\src\crystal\system\win32\file_descriptor.cr:46 in 'unbuffered_write'
from C:\Users\user\AppData\Roaming\crimson\crystal\1.9.2\src\io\buffered.cr:239 in 'flush'
from C:\Users\user\AppData\Roaming\crimson\crystal\1.9.2\src\io\buffered.cr:178 in 'write_byte'
from C:\Users\user\AppData\Roaming\crimson\crystal\1.9.2\src\char.cr:983 in 'to_s'
from C:\Users\user\AppData\Roaming\crimson\crystal\1.9.2\src\io.cr:177 in '<<'
from C:\Users\user\AppData\Roaming\crimson\crystal\1.9.2\src\io.cr:191 in 'print'
from C:\Users\user\AppData\Roaming\crimson\crystal\1.9.2\src\io.cr:246 in 'puts'
from C:\Users\user\AppData\Roaming\crimson\crystal\1.9.2\src\io.cr:235 in 'puts'
from C:\Users\user\AppData\Roaming\crimson\crystal\1.9.2\src\kernel.cr:418 in 'puts'
from .\eval:1 in '__crystal_main'
from C:\Users\user\AppData\Roaming\crimson\crystal\1.9.2\src\crystal\main.cr:129 in 'main_user_code'
from C:\Users\user\AppData\Roaming\crimson\crystal\1.9.2\src\crystal\main.cr:115 in 'main'
from C:\Users\user\AppData\Roaming\crimson\crystal\1.9.2\src\crystal\main.cr:141 in 'main'
from C:\Users\user\AppData\Roaming\crimson\crystal\1.9.2\src\crystal\system\win32\wmain.cr:37 in 'wmain'
from d:\a01\_work\12\s\src\vctools\crt\vcstartup\src\startup\exe_common.inl:288 in '__scrt_common_main_seh'
from C:\WINDOWS\System32\KERNEL32.DLL +75133 in 'BaseThreadInitThunk'
from C:\WINDOWS\SYSTEM32\ntdll.dll +371304 in 'RtlUserThreadStart' To make things even weirder, this can go up to ~700 times before throwing an exception. Running the following produced this: C:\...> crystal eval "i=0; loop do (puts :hello; i+=1) rescue (STDERR.puts i; exit) end" | .\head
hello
hello
hello
766 I repeated this command 15 times in 3 separate processes, it averaged around 767 with the highest being 795. |
@devnote-dev Golang seems to be doing as described in #7810 (comment) only on Unix. On Windows this functionality does not exist (probably there is no equivalent to raise SIGPIPE). |
Code to reproduce:
Then, when I try to pipe with command:
This error output occurs:
version:
The text was updated successfully, but these errors were encountered: