Project

General

Profile

Actions

Bug #18244

closed

Unexpected errors output order

Added by inversion (Yura Babak) about 2 months ago. Updated 3 days ago.

Status:
Closed
Priority:
Normal
Assignee:
-
Target version:
-
ruby -v:
Ruby v3.0.2.107 (2021-07-07) [x64-mingw32]
[ruby-core:105586]

Description

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]

Updated by nobu (Nobuyoshi Nakada) about 2 months ago

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

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?

Updated by inversion (Yura Babak) about 2 months ago

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.

Updated by nobu (Nobuyoshi Nakada) about 2 months ago

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

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

Updated by inversion (Yura Babak) about 2 months ago

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.

Updated by Eregon (Benoit Daloze) about 2 months ago

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.

Updated by inversion (Yura Babak) about 2 months ago

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!

Updated by Eregon (Benoit Daloze) about 2 months ago

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.

Actions #8

Updated by nobu (Nobuyoshi Nakada) 3 days ago

  • Status changed from Feedback to Closed
Actions

Also available in: Atom PDF