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:

OpenStudio/src/cli/UpdateCommand.cpp

Lines 58 to 90 in 5de13e3

	void executeRubyScriptCommand(openstudio::path rubyScriptPath, ScriptEngineInstance& rubyEngine, const std::vector<std::string>& arguments) {
	rubyScriptPath = openstudio::filesystem::system_complete(rubyScriptPath);
	LOG_FREE(Debug, "executeRubyScriptCommand", "Path for the file to run: " << rubyScriptPath);
	if (!openstudio::filesystem::is_regular_file(rubyScriptPath)) {
	throw std::runtime_error(fmt::format("Unable to find the file '{}' on the filesystem", rubyScriptPath.string()));
	}
	std::string cmd = "ARGV.clear\n";
	for (const auto& arg : arguments) {
	cmd += fmt::format("ARGV << \"{}\"\n", arg);
	}
	cmd += fmt::format(R"(
	begin
	require '{}'
	rescue SystemExit
	# puts "help was called"
	rescue Exception => e
	puts
	puts "Error: #{{e.message}}"
	puts "Backtrace:\n\t" + e.backtrace.join("\n\t")
	raise
	end
	)",
	rubyScriptPath.generic_string());
	try {
	rubyEngine->exec(cmd);
	} catch (...) {
	// Bail faster though ruby isn't slow like python
	fmt::print(stderr, "Failed to execute '{}'\n", rubyScriptPath.generic_string());
	exit(1);
	// throw std::runtime_error(fmt::format("Failed to execute '{}'\n", rubyScriptPath.generic_string()));
	}
	}

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 #5052 (comment) again.

Basically @wenyikuang reported some failures to run openstudio --bundle and I realized, once again, that our tests

OpenStudio/src/cli/test/test_bundle.rb

Lines 16 to 28 in 969f480

	def test_bundle
	original_dir = Dir.pwd
	Dir.chdir(File.join(File.dirname(__FILE__), 'bundle'))
	rm_if_exist('Gemfile.lock')
	rm_if_exist('./test_gems')
	rm_if_exist('./bundle')
	assert(system('bundle install --path ./test_gems'))
	assert(system('bundle lock --add_platform ruby'))
	assert(system("'#{OpenStudio::getOpenStudioCLI}' --bundle Gemfile --bundle_path './test_gems' --verbose test.rb"))
	ensure

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]

• "exit 1" in ruby code is silently dismissed #5162