[ruby-core:105586] [Ruby master Bug#18244] Unexpected errors output order

[ruby-core:105586] [Ruby master Bug#18244] Unexpected errors output order

[inversion (Yura Babak)]

Issue #18244 has been reported by inversion (Yura Babak).

----------------------------------------
Bug #18244: Unexpected errors output order
https://bugs.ruby-lang.org/issues/18244

* Author: inversion (Yura Babak)
* Status: Open
* Priority: Normal
* ruby -v: Ruby v3.0.2.107 (2021-07-07) [x64-mingw32]
* Backport: 2.6: UNKNOWN, 2.7: UNKNOWN, 3.0: UNKNOWN
----------------------------------------
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]`



-- 
https://bugs.ruby-lang.org/

[ruby-core:105589] [Ruby master Bug#18244] Unexpected errors output order

[nobu (Nobuyoshi Nakada)]

Issue #18244 has been updated by nobu (Nobuyoshi Nakada).

Status changed from Open to Feedback
Description updated

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?

----------------------------------------
Bug #18244: Unexpected errors output order
https://bugs.ruby-lang.org/issues/18244#change-94057

* Author: inversion (Yura Babak)
* Status: Feedback
* Priority: Normal
* ruby -v: Ruby v3.0.2.107 (2021-07-07) [x64-mingw32]
* Backport: 2.6: UNKNOWN, 2.7: UNKNOWN, 3.0: UNKNOWN
----------------------------------------
Having this code:
```ruby
# $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]`



-- 
https://bugs.ruby-lang.org/

[ruby-core:105590] [Ruby master Bug#18244] Unexpected errors output order

[inversion (Yura Babak)]

Issue #18244 has been updated by 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.


----------------------------------------
Bug #18244: Unexpected errors output order
https://bugs.ruby-lang.org/issues/18244#change-94058

* Author: inversion (Yura Babak)
* Status: Feedback
* Priority: Normal
* ruby -v: Ruby v3.0.2.107 (2021-07-07) [x64-mingw32]
* Backport: 2.6: UNKNOWN, 2.7: UNKNOWN, 3.0: UNKNOWN
----------------------------------------
Having this code:
```ruby
# $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]`



-- 
https://bugs.ruby-lang.org/

[ruby-core:105591] [Ruby master Bug#18244] Unexpected errors output order

[nobu (Nobuyoshi Nakada)]

Issue #18244 has been updated by nobu (Nobuyoshi Nakada).


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

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

----------------------------------------
Bug #18244: Unexpected errors output order
https://bugs.ruby-lang.org/issues/18244#change-94060

* Author: inversion (Yura Babak)
* Status: Feedback
* Priority: Normal
* ruby -v: Ruby v3.0.2.107 (2021-07-07) [x64-mingw32]
* Backport: 2.6: UNKNOWN, 2.7: UNKNOWN, 3.0: UNKNOWN
----------------------------------------
Having this code:
```ruby
# $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]`



-- 
https://bugs.ruby-lang.org/

[ruby-core:105596] [Ruby master Bug#18244] Unexpected errors output order

[inversion (Yura Babak)]

Issue #18244 has been updated by 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.


----------------------------------------
Bug #18244: Unexpected errors output order
https://bugs.ruby-lang.org/issues/18244#change-94067

* Author: inversion (Yura Babak)
* Status: Feedback
* Priority: Normal
* ruby -v: Ruby v3.0.2.107 (2021-07-07) [x64-mingw32]
* Backport: 2.6: UNKNOWN, 2.7: UNKNOWN, 3.0: UNKNOWN
----------------------------------------
Having this code:
```ruby
# $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]`



-- 
https://bugs.ruby-lang.org/

[ruby-core:105601] [Ruby master Bug#18244] Unexpected errors output order

[Eregon (Benoit Daloze)]

Issue #18244 has been updated by 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.

----------------------------------------
Bug #18244: Unexpected errors output order
https://bugs.ruby-lang.org/issues/18244#change-94081

* Author: inversion (Yura Babak)
* Status: Feedback
* Priority: Normal
* ruby -v: Ruby v3.0.2.107 (2021-07-07) [x64-mingw32]
* Backport: 2.6: UNKNOWN, 2.7: UNKNOWN, 3.0: UNKNOWN
----------------------------------------
Having this code:
```ruby
# $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]`



-- 
https://bugs.ruby-lang.org/

[ruby-core:105604] [Ruby master Bug#18244] Unexpected errors output order

[inversion (Yura Babak)]

Issue #18244 has been updated by 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!


----------------------------------------
Bug #18244: Unexpected errors output order
https://bugs.ruby-lang.org/issues/18244#change-94085

* Author: inversion (Yura Babak)
* Status: Feedback
* Priority: Normal
* ruby -v: Ruby v3.0.2.107 (2021-07-07) [x64-mingw32]
* Backport: 2.6: UNKNOWN, 2.7: UNKNOWN, 3.0: UNKNOWN
----------------------------------------
Having this code:
```ruby
# $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]`



-- 
https://bugs.ruby-lang.org/

[ruby-core:105606] [Ruby master Bug#18244] Unexpected errors output order

[Eregon (Benoit Daloze)]

Issue #18244 has been updated by 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 decide.
Although I'm not against nobu's patch, I think it is reasonably expected behavior when using `$stderr.sync = false`.

----------------------------------------
Bug #18244: Unexpected errors output order
https://bugs.ruby-lang.org/issues/18244#change-94088

* Author: inversion (Yura Babak)
* Status: Feedback
* Priority: Normal
* ruby -v: Ruby v3.0.2.107 (2021-07-07) [x64-mingw32]
* Backport: 2.6: UNKNOWN, 2.7: UNKNOWN, 3.0: UNKNOWN
----------------------------------------
Having this code:
```ruby
# $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]`



-- 
https://bugs.ruby-lang.org/