Error messages not captured with exit codes

[joseph-robertson]

Issue overview

For a ruby script called by the CLI, fail "xxx" has different behavior between 3.6.1 and 3.7.0.

Current Behavior

You can output capture (e.g., using "`" characters) the fail statement.

Expected Behavior

The fail statement output is no longer captured.

Steps to Reproduce

run_analysis.rb.txt test_fail.rb.txt

Possible Solution

Details

Environment

Some additional details about your environment for this issue (if relevant):

• Platform (Operating system, version): Windows
• Version of OpenStudio (if using an intermediate build, include SHA): 3.6.1 vs. 3.7.1

Context

This breaks some of our tests for ResStock.

[joseph-robertson]

From @jmarrec:

It’s a corner case... We’ve had to put some fail-safe / error handling in the CLI in a bunch of places to avoid issues (...), and we haven’t though of this one But this is going to to affect measure testing for a lot of users (especially NREL users), so it should be investigated and fixed/mitigated

[jmarrec]

Ok, so I initially thought the only difference was that the C++ CLI will report this error to stderr, when the backticks in ruby capture only stdout, but this isn't what's happening.

The Failed to execute '/path/to/script.rb' is indeed reported to stdout. The backtrace, which includes the string we look for, is reported to stdout correctly when run from the command line:

$ openstudio run_analysis.rb --fail 2> /dev/null

Error: Threw a fail statement.
Backtrace:
    /home/julien/Software/Others/OpenStudio/src/cli/test/run_analysis.rb:30:in `<top (required)>'
    eval:139:in `require'
    eval:139:in `require'
    :/ruby/2.7.0/rubygems/core_ext/kernel_require.rb:92:in `require'
    eval:5:in `<main>'

The issue is that the scripting language does not see that STDOUT bit.

In ruby:

[1] test(main)> @command = "openstudio run_analysis.rb -f"

[2] test(main)> system(@command)

Error: Threw a fail statement.
Backtrace:
    /home/julien/Software/Others/OpenStudio/src/cli/test/run_analysis.rb:30:in `<top (required)>'
    eval:139:in `require'
    eval:139:in `require'
    :/ruby/2.7.0/rubygems/core_ext/kernel_require.rb:92:in `require'
    eval:5:in `<main>'
Failed to execute '/home/julien/Software/Others/OpenStudio/src/cli/test/run_analysis.rb'

[3] test(main)> o, e, s = Open3.capture3("openstudio run_analysis.rb -f")
=> ["", "Failed to execute '/home/julien/Software/Others/OpenStudio/src/cli/test/run_analysis.rb'\n", #<Process::Status: pid 33552 exit 1>]

The bit that prints the backtrace is here:

https://github.com/NREL/OpenStudio/blob/5de13e37adc429fce907e3c061ee86f4cdf171a9/src/cli/UpdateCommand.cpp#L58-L90

It's possible this is a flushing issue.

[jmarrec]

ok, so I can fix it by explicitly flushing STDOUT from ruby.

I'd advocate that this should NOT have been reported to stdout but to stderr... But obviously, that's a change from the classic CLI, so I'm not sure what to do here. @kbenne @joseph-robertson thoughts please?

That'd mean if you explictly wanted to test the failure messages, you'd have to make a spec helper like this

require 'open3'
stdout, stderr, status = Open3.capture3(@command)

Or this (untested on windows):

`#{@command} 2>&1`

[jmarrec]

Hum, closely related is the fact that if you run a file that has minitests in it via the CLI, the return code is 0 even if the tests fail... the classic CLI has the same issue though

(test) $ ruby test_fail_stdout.rb -n test_ruby_fail_backticks
Run options: -n test_ruby_fail_backticks --seed 10755

# Running:

Failed to execute '/Users/julien/Software/Others/OpenStudio/src/cli/test/./execute_ruby_script_fail.rb'
F

Finished in 0.412776s, 2.4226 runs/s, 4.8452 assertions/s.

  1) Failure:
FailTest#test_ruby_fail_backticks [test_fail_stdout.rb:24]:
Expected "" to include "Error: Threw a fail statement.".

1 runs, 2 assertions, 1 failures, 0 errors, 0 skips
(test) $ echo $?
1

----

(test) $ openstudio test_fail_stdout.rb -n test_ruby_fail_backticks
Run options: -n test_ruby_fail_backticks --seed 31024

# Running:

Failed to execute '/Users/julien/Software/Others/OpenStudio/src/cli/test/execute_ruby_script_fail.rb'
F

Finished in 0.896169s, 1.1159 runs/s, 2.2317 assertions/s.

  1) Failure:
FailTest#test_ruby_fail_backticks [/Users/julien/Software/Others/OpenStudio/src/cli/test/test_fail_stdout.rb:24]:
Expected "" to include "Error: Threw a fail statement.".

1 runs, 2 assertions, 1 failures, 0 errors, 0 skips
(test) $ echo $?
0

[jmarrec]

@kbenne I'm bumping into this https://github.com/NREL/OpenStudio/issues/5052#issuecomment-1892509628 again.

Basically @wenyikuang reported some failures to run openstudio --bundle and I realized, once again, that our tests https://github.com/NREL/OpenStudio/blob/969f480657abf5c11f2e892e1cbcce3b6e8734be/src/cli/test/test_bundle.rb#L16-L28

have been failing for a while, it's just that CMake doesn't see the issue.

3888: # Running:
3888: 
3888: [DEPRECATED] The `--path` flag is deprecated because it relies on being remembered across bundler invocations, which bundler will no longer do in future versions. Instead please use `bundle config set path './test_gems'`, and stop using this flag
3888: Fetching gem metadata from http://rubygems.org/........
3888: Resolving dependencies...
3888: Could not find compatible versions
3888: 
3888: Because openstudio-workflow >= 2.2.0 depends on Ruby ~> 2.7.0
3888:   and Gemfile depends on openstudio-workflow = 2.2.0,
3888:   Ruby ~> 2.7.0 is required.
3888: So, because current Ruby version is = 3.2.2,
3888:   version solving has failed.
3888: F
3888: 
3888: Finished in 1.558711s, 0.6416 runs/s, 0.6416 assertions/s.
3888: 
3888:   1) Failure:
3888: Bundle_Test#test_bundle [/home/julien/Software/Others/OpenStudio/src/cli/test/test_bundle.rb:24]:
3888: Expected false to be truthy.
3888: 
3888: 1 runs, 1 assertions, 1 failures, 0 errors, 0 skips
1/5 Test #3888: CLITest-test_bundle-bundle ..............   Passed   19.43 sec

[jmarrec]

• https://github.com/NREL/OpenStudio/issues/5162