OpenStudio logging singleton issues (especially on Windows) when using interpreted bindings (ruby measures)

[shorowit]

Issue overview

Two issues observed comparing the behavior of OpenStudio logging between Linux and Windows:

1. Windows produces more warning messages than appear on Linux. Why?! I primarily do my testing on Linux, so I'm concerned that I might be missing things.

--- C:/Users/shorowit/Desktop/Linux.txt	Thu Mar 30 15:24:05 2023
+++ C:/Users/shorowit/Desktop/Windows.txt	Thu Mar 30 15:23:57 2023
@@ -3,2 +3,5 @@
 [openstudio.measure.OSRunner] <1> Cannot find current Workflow Step
+[openstudio.measure.OSRunner] <1> Cannot find current Workflow Step
+[openstudio.EpwFile] <0> Successive data points (1995-Jan-31 to 1994-Feb-01, ending on line 753) are greater than 1 day apart in EPW file 'C:/git/openstudio-hpxml/HPXMLtoOpenStudio/resources/../../weather/USA_CO_Denver.Intl.AP.725650_TMY3.epw'. Data will be treated as typical (TMY)
+[openstudio.WorkflowStepResult] <0> WorkflowStepResult value called with undefined stepResult, returning 'Success'
 Running simulation...
@@ -8,2 +11,6 @@
 [openstudio.measure.OSRunner] <1> Cannot find current Workflow Step
+[openstudio.WorkflowStepResult] <0> WorkflowStepResult value called with undefined stepResult, returning 'Success'
+[openstudio.measure.OSRunner] <1> Cannot find current Workflow Step
+[openstudio.measure.OSRunner] <1> Cannot find current Workflow Step
+[openstudio.WorkflowStepResult] <0> WorkflowStepResult value called with undefined stepResult, returning 'Success'
 Wrote output file: run/results_annual.csv.

2. When using OpenStudio::Logger.instance.standardOutLogger.setLogLevel(OpenStudio::Fatal) to suppress warning messages, warnings are completely suppressed on Linux but not on Windows. For some of our workflows, this means we can get dozens and dozens of lines of output on Windows, which is annoying and makes it difficult to see the output of interest.

--- C:/Users/shorowit/Desktop/Linux.txt	Thu Mar 30 15:24:02 2023
+++ C:/Users/shorowit/Desktop/Windows.txt	Thu Mar 30 15:24:00 2023
@@ -2,2 +2,5 @@
 Creating input...
+[openstudio.measure.OSRunner] <1> Cannot find current Workflow Step
+[openstudio.EpwFile] <0> Successive data points (1995-Jan-31 to 1994-Feb-01, ending on line 753) are greater than 1 day apart in EPW file 'C:/git/openstudio-hpxml/HPXMLtoOpenStudio/resources/../../weather/USA_CO_Denver.Intl.AP.725650_TMY3.epw'. Data will be treated as typical (TMY)
+[openstudio.WorkflowStepResult] <0> WorkflowStepResult value called with undefined stepResult, returning 'Success'
 Running simulation...
@@ -5,2 +8,6 @@
 Processing output...
+[openstudio.measure.OSRunner] <1> Cannot find current Workflow Step
+[openstudio.WorkflowStepResult] <0> WorkflowStepResult value called with undefined stepResult, returning 'Success'
+[openstudio.measure.OSRunner] <1> Cannot find current Workflow Step
+[openstudio.WorkflowStepResult] <0> WorkflowStepResult value called with undefined stepResult, returning 'Success'
 Wrote output file: run/results_annual.csv.

Expected Behavior

OpenStudio should behave the same on Linux and Windows.

Steps to Reproduce

1. Clone https://github.com/NREL/OpenStudio-HPXML
2. To reproduce issue 1, run openstudio workflow/run_simulation.rb -x workflow/sample_files/base.xml -o test on Windows and Linux.
3. To reproduce issue 2, comment out this line and run the above command again on Windows and Linux.

Details

Environment

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

• Windows 10 and Ubuntu 20.04 (WSL)
• OpenStudio 3.5

[jmarrec]

Oh great, another one of the "Windows" v "Linux" difference type :)

Any chance you have a MCVE that doesn't involve a complex gem like OpenStudio-HPXML? Something like openstudio run -w in.osw with a minimal model.cat

FWIW, the EPW you use is supposed to issue a 0 = OpenStudio::Warn log message

Using Ubuntu 20.04, in pry:

epw = OpenStudio::EpwFile.new('weather/USA_CO_Denver.Intl.AP.725650_TMY3.epw')
[openstudio.EpwFile] <0> Successive data points (1995-Jan-31 to 1994-Feb-01, ending on line 753) are greater than 1 day apart in EPW file 'weather/USA_CO_Denver.Intl.AP.725650_TMY3.epw'. Data will be treated as typical (TMY)

[jmarrec]

Well actually I can reproduce using only the compact_ruby_only.osw we have in source.

(py39)julien@compact_osw$ $os_build_rel3/Products/openstudio run -w compact_ruby_only.osw
[11:59:34.530107 WARN] Measure couldn't find the construction named 'EXTERIOR-WALL adj exterior wall insulation' in the exterior surface hash.
(py39)julien@compact_osw$ cat run/run.log 
[11:59:34.530107 WARN] Measure couldn't find the construction named 'EXTERIOR-WALL adj exterior wall insulation' in the exterior surface hash

$ C:\src\OpenStudio\build-release\Products\openstudio.exe run -w compact_ruby_only.osw
[OpenStudio.Measure] <0> OSRunner is deprecated, use OpenStudio::Measure::OSRunner instead.
[openstudio.EpwFile] <0> Header start day of the week and actual start day of the week do not match in EPW file 'C:/src/OpenStudio/build-debug/resources/Examples/compact_osw/files/srrl_2013_amy.epw'. Data will be treated as typical (TMY)
[OpenStudio.Measure] <0> OSArgumentMap is deprecated, use OpenStudio::Measure::OSArgumentMap instead.
[OpenStudio.Measure] <0> OSArgumentMap is deprecated, use OpenStudio::Measure::OSArgumentMap instead.
[12:04:09.179426 WARN] Measure couldn't find the construction named 'EXTERIOR-WALL adj exterior wall insulation' in the exterior surface hash.
[openstudio.energyplus.ForwardTranslator] <0> OS_ProgramControl is not currently translated
[utilities.idf.WorkspaceObject] <0> Object of type 'Schedule:Constant' and named 'Always Off Discrete', points to an object named OnOff from field 1, but that object cannot be located.
[utilities.idf.WorkspaceObject] <0> Object of type 'Schedule:Constant' and named 'Always On Continuous', points to an object named Fractional 1 from field 1, but that object cannot be located.
[OpenStudio.Measure] <0> OSArgumentMap is deprecated, use OpenStudio::Measure::OSArgumentMap instead.
[OpenStudio.Measure] <0> OSArgumentMap is deprecated, use OpenStudio::Measure::OSArgumentMap instead.
[OpenStudio.Measure] <0> OSArgumentMap is deprecated, use OpenStudio::Measure::OSArgumentMap instead.
$  cat .\run\run.log
[12:04:09.179426 WARN] Measure couldn't find the construction named 'EXTERIOR-WALL adj exterior wall insulation' in the exterior surface hash.

The labs doesn't have the same issue (but I realize it outputs everything to run.log though), so this is likely a ruby-side issue. I'll look into it

[jmarrec]

https://github.com/NREL/OpenStudio/blob/33626993b6315a614eb67de7b158bf4e5fb384d9/ruby/engine/openstudio_cli.rb#L49-L56

[jmarrec]

Ok, here is a proper MCVE:

$logger = Logger.new(STDOUT)
$logger.level = Logger::WARN

OpenStudio::Logger.instance.standardOutLogger.setLogLevel(OpenStudio::Error)

$logger.info "STDOUT Info"
$logger.warn "STDOUT Warn"
$logger.error "STDOUT Error"

OpenStudio::logFree(OpenStudio::Info, "test", "Info")
OpenStudio::logFree(OpenStudio::Warn, "test", "Warn")
OpenStudio::logFree(OpenStudio::Error, "test", "Error")

Unix behaves correctly:

$ openstudio test.rb
W, [2023-04-04T12:21:56.062121 #230289]  WARN -- : STDOUT Warn
E, [2023-04-04T12:21:56.062161 #230289] ERROR -- : STDOUT Error
[test] <1> Error

Windows shows the issue. Seems like both the stdout logger and the SDK logger are intertwined:

$ openstudio.exe .\test.rb
W, [2023-04-04T12:22:32.765676 #15076]  WARN -- : STDOUT Warn
E, [2023-04-04T12:22:32.766081 #15076] ERROR -- : STDOUT Error
[test] <0> Warn
[test] <1> Error
[test] <1> Error

[jmarrec]

And here we are... We broke something during the labs work

$ C:\Users\julien\Downloads\OpenStudio-3.4.0+9e989dbeea-Windows\bin\openstudio.exe .\test.rb
W, [2023-04-04T12:33:42.759688 #14548]  WARN -- : STDOUT Warn
E, [2023-04-04T12:33:42.760148 #14548] ERROR -- : STDOUT Error
[test] <1> Error
$ C:\Users\julien\Downloads\OpenStudio-3.5.0+7b14ce1588-Windows\bin\openstudio.exe .\test.rb
W, [2023-04-04T12:34:13.628220 #11696]  WARN -- : STDOUT Warn
E, [2023-04-04T12:34:13.628766 #11696] ERROR -- : STDOUT Error
[test] <0> Warn
[test] <1> Error
[test] <1> Error

@kbenne My money is on the use of a shared lib for ruby: 50f6c03 . Thoughts?

I think we basically have one logger in the libopenstudiolib and ANOTHER one in the ruby shared lib.
The Ruby shared lib one is correctly set to log level = Error, but the other one is still set to the default of Warn. https://github.com/NREL/OpenStudio/blob/33626993b6315a614eb67de7b158bf4e5fb384d9/src/utilities/core/Logger.cpp#L54

Both are triggered... which explains why issuing an Info shows 0 message, Warn shows 1 message, and anything Error or above shows 2 messages.

[jmarrec]

On windows, if here I modify this line: https://github.com/NREL/OpenStudio/blob/33626993b6315a614eb67de7b158bf4e5fb384d9/src/cli/main.cpp#L299

to be

+   // Disable this logger, we have a duplicate in the ruby shared lib
+   openstudio::Logger::instance().standardOutLogger().disable();
+   openstudio::Logger::instance().standardErrLogger().disable();
    result = openstudio::rubyCLI(rubyEngine);

Then past the initial extra messages issued when we locate the DLL via getOpenStudioModule, I get only one set of messages

$ Products\openstudio.exe execute_ruby_script .\resources\Examples\compact_osw\test.rb
[2023-04-04 13:14:08.970602] [0x00003a00] [info]    getOpenStudioModule, szPath = 'C:\src\OpenStudio\build-debug\Products\openstudiolib.dll'
[2023-04-04 13:14:08.973631] [0x00003a00] [info]    completeAndNormalize: looking for p = C:/src/OpenStudio/build-debug/Products/openstudiolib.dll
[2023-04-04 13:14:08.974637] [0x00003a00] [info]    completeAndNormalize: temp = C:/src/OpenStudio/build-debug/Products/openstudiolib.dll
[2023-04-04 13:14:08.981796] [0x00003a00] [info]    completeAndNormalize: result = C:/src/OpenStudio/build-debug/Products/openstudiolib.dll
[2023-04-04 13:14:08.982718] [0x00003a00] [info]    getOpenStudioModule, found 'C:/src/OpenStudio/build-debug/Products/openstudiolib.dll'

W, [2023-04-04T13:14:13.052013 #6864]  WARN -- : STDOUT Warn
E, [2023-04-04T13:14:13.052447 #6864] ERROR -- : STDOUT Error
[test] <1> Error