Bug #18244: Unexpected errors output order

• Status: Closed
• Assignee: -
• Target version: -
• ruby -v: Ruby v3.0.2.107 (2021-07-07) [x64-mingw32]
• Backport: 2.6: UNKNOWN, 2.7: UNKNOWN, 3.0: UNKNOWN

[inversion (Yura Babak)]

Having this code:

# $stderr.sync = false
warn 'warn'
$stderr.puts 'err'
fail

When I run it like this ruby test.rb 2>err.log, output is ok:

warn
err
test.rb:3:in `<main>': unhandled exception

But when I uncomment the first line — the output is different:

warn
test.rb:3:in `<main>': unhandled exception
err

Why buffered output to the $stderr redirected to file has the wrong order?
If we do not redirect to the file — the order is ok (exception is the last line of the output).

Checked platforms:
Windows10: Ruby v3.0.2.107 (2021-07-07) [x64-mingw32]
Linux: Ruby 3.0.0p0 (2020-12-25 revision 95aff21468) [x86_64-linux]

[nobu (Nobuyoshi Nakada)]

• Description updated (diff)
• Status changed from Open to Feedback

Of course it's possible to make flushing stderr at error handling, but it also can make a chance of another exception.
Do you have any reason to make stderr unbuffered?

[inversion (Yura Babak)]

Do you have any reason to make stderr unbuffered?

I do add records to stdout within a cycle, so it is better to have it buffered for better overall performance. Also, I have few parallel workers in threads with such cycles. As a result, when some worker crashes (and app terminated) — in the log there is an error output and after it a lot of regular outputs from other workers, so it is very hard to find out in which iteration error actually happened.

[nobu (Nobuyoshi Nakada)]

It sounds hard anyway regardless stderr buffering.
Why mixing stdout and stderr?

https://github.com/ruby/ruby/pull/4944

[inversion (Yura Babak)]

Why mixing stdout and stderr?

I have a script that is running periodically in the background on another machine. Sometimes I visit that machine and review logs.
My goal is to see a full story in the log, the same as we can see when running in the terminal.
For that I use the next running command:
ruby task.rb >> log.txt 2>&1
And I would like to see any crash exception as the last thing (as it is in the terminal), not in the middle of all the outputs regardless the buffering. So by outputs order, I can analyze the sequence of the last operations.
Maybe there is some other approach to achieve this?

This issue that the final exception ignores buffering, gave me hard times analyzing logs until I realized that it is impossible order of outputs and it is just the wrong output order to file.

[Eregon (Benoit Daloze)]

I believe the real issue here is to $stderr.sync = false, why do you do that?
That's like explicitly breaking what you are asking.

If it's for performance because you are writing a lot to stderr, then why are you writing so much to stderr?

This is not only about exceptions, with $stderr.sync = false the output will be interleaved in unclear ways anyway.
Maybe you want something like $stderr = $stdout so both are actually the same and use a single buffer?
Both $stderr and $stdout unbuffered would also work.

[inversion (Yura Babak)]

I believe the real issue here is to $stderr.sync = false, why do you do that?
That's like explicitly breaking what you are asking.

Having buffered $stdout I thought that $stderr.sync = false will make $stderr to be in sync with $stdout. Now I understand that it was not the best solution.

why are you writing so much to stderr

I don't, I only wanted to see the error in the right place among many regular buffered outputs.

Maybe you want something like $stderr = $stdout so both are actually the same and use a single buffer?

I just tested it and yes, it is exactly what I wanted to achieve — single buffered output for all.
Thank you very much!

[Eregon (Benoit Daloze)]

Glad to have helped :)
And I am sorry if my reply sounded harsh.

I think we can close this, I'll let @nobu (Nobuyoshi Nakada) decide.
Although I'm not against nobu's patch, I think it is reasonably expected behavior when using $stderr.sync = false.

[nobu (Nobuyoshi Nakada)]

• Status changed from Feedback to Closed