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

shorowit · 2023-03-30T21:35:07Z

Issue overview

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

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.

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

Clone https://github.com/NREL/OpenStudio-HPXML
To reproduce issue 1, run openstudio workflow/run_simulation.rb -x workflow/sample_files/base.xml -o test on Windows and Linux.
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

The text was updated successfully, but these errors were encountered:

jmarrec · 2023-04-04T10:03:07Z

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 · 2023-04-04T10:05:18Z

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 · 2023-04-04T10:07:00Z

OpenStudio/ruby/engine/openstudio_cli.rb

Lines 49 to 56 in 3362699

    
           $logger = Logger.new(STDOUT) 
        
           #$logger.level = Logger::ERROR 
        
           $logger.level = Logger::WARN 
        
           #$logger.level = Logger::DEBUG 
        
           #OpenStudio::Logger.instance.standardOutLogger.disable 
        
           #OpenStudio::Logger.instance.standardOutLogger.setLogLevel(OpenStudio::Warn) 
        
           OpenStudio::Logger.instance.standardOutLogger.setLogLevel(OpenStudio::Error)

jmarrec · 2023-04-04T10:24:15Z

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 · 2023-04-04T10:36:11Z

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.

OpenStudio/src/utilities/core/Logger.cpp

Line 54 in 3362699

m_standardOutLogger.setLogLevel(Warn);

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 · 2023-04-04T11:29:09Z

On windows, if here I modify this line:

OpenStudio/src/cli/main.cpp

Line 299 in 3362699

result = openstudio::rubyCLI(rubyEngine);

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

…ruby shared lib has a duplicated one...

…thon file

…ruby shared lib has a duplicated one...

…thon file

…ruby shared lib has a duplicated one...

Fix #4847 - OpenStudio logging behaves differently on Windows/Linux

shorowit · 2024-01-05T21:36:58Z

@jmarrec You had fixed this issue, but it's no longer working for Windows w/ OS 3.7. You can easily reproduce the issue by cloning OpenStudio-HPXML and running openstudio tasks.rb update_hpxmls. We are using OpenStudio::Logger.instance.standardOutLogger.setLogLevel(OpenStudio::Fatal) to try to suppress messages.

Linux w/ C++ CLI:

Windows w/ C++ CLI:

shorowit · 2024-01-12T16:26:38Z

I was doing some more testing and realized this broke w/ the switch to the C++ CLI. It's easy to confirm because you can use the 3.7.0 release of OpenStudio and run the above command using classic or not. When running with classic the standardOutLogger's log level is correctly used (see below); when running w/o classic, it is not (see above).

Windows w/ classic CLI:

jmarrec · 2024-01-15T08:55:41Z

@shorowit I guess it was misleading having closed this issue. What I did was a mere workaround for the "classic" version in 8301544 .
We've had a failing test since for the labs version.

The issue is that the Logger is a Static Singleton. And We get one in the libopenstudiolib, but we also get one in the rubyengine and one in the pythonengine (which are dlopened). So we end up with several logger instances... I don't know how to resolve that situation yet, and I reckon we'll need @kbenne 's magic touch for this.

This is an effort to elliminate the possibility of openstudio::Singleton<openstudiio::Logger>::instance being non unique across the ScriptEngine boundary. A new custom Logger singleton has been introduced that allows us to pass a Logger pointer from the main cli program into the script engine. This should give us a guarantee that the Ruby/Python script engines do not spawn their own unique loggers. This is an experiment and subject to review and refinement. ref #4847

Previously, we used the openstudio::Singleton template to create the singleton named Logger. This implementation suffered a bug described in #4847, where the singleton was not global across the ScriptEngine DLL boundary. This change is a non templated implementation of Logger. The design is identical to openstudio::Singleton<LoggerSingleton>, but does not suffer the non-global issue. ref #4847

kbenne · 2024-02-16T17:22:51Z

Testing changes to logger.hpp can be very time consuming, since it typically triggers large rebuilds. I have tested iterations of a fix to this over in the Labs repo. https://github.com/NREL/OpenStudioLabs/tree/logger-singleton

shorowit · 2024-02-19T16:40:11Z

Let me know if you want me to test a dev build at some point, happy to kick the tires on any proposed solution.

ref #4847

Previously, we used the openstudio::Singleton template to create the singleton named Logger. This implementation suffered a bug described in #4847, where the singleton was not global across the ScriptEngine DLL boundary. This change is a non templated implementation of Logger. The design is identical to openstudio::Singleton<LoggerSingleton>, but does not suffer the non-global issue. ref #4847

ref #4847

Previously, we used the openstudio::Singleton template to create the singleton named Logger. This implementation suffered a bug described in #4847, where the singleton was not global across the ScriptEngine DLL boundary. This change is a non templated implementation of Logger. The design is identical to openstudio::Singleton<LoggerSingleton>, but does not suffer the non-global issue. ref #4847

ref #4847

kbenne · 2024-03-28T16:16:44Z

@shorowit and @joseph-robertson

This should be in a state that we could use your testing on it.

shorowit · 2024-04-30T14:59:48Z

Re-tested these issues in the 3.8-rc1 and they seem to work as expected now. Thanks @kbenne and @jmarrec!

shorowit added the Triage Issue needs to be assessed and labeled, further information on reported might be needed label Mar 30, 2023

tijcolem added component - Utilities Other severity - Normal Bug and removed Triage Issue needs to be assessed and labeled, further information on reported might be needed labels Mar 31, 2023

jmarrec added a commit that referenced this issue Apr 4, 2023

Workaround for #4847 - Disable the libopenstudiolib logger since the …

ea91d37

…ruby shared lib has a duplicated one...

jmarrec added a commit that referenced this issue Apr 5, 2023

Add ctests for #4847 via a python script calling the CLI on a ruby/py…

19f81dc

…thon file

jmarrec mentioned this issue Apr 5, 2023

Fix #4847 - OpenStudio logging behaves differently on Windows/Linux #4852

Merged

19 tasks

jmarrec added a commit that referenced this issue Apr 5, 2023

Add ctests for #4847 via a python script calling the CLI on a ruby/py…

2333de2

…thon file

jmarrec added a commit that referenced this issue Apr 5, 2023

Workaround for #4847 - Disable the libopenstudiolib logger since the …

992da3a

…ruby shared lib has a duplicated one...

tijcolem modified the milestone: OpenStudio SDK 3.7.0 Apr 21, 2023

jmarrec added a commit that referenced this issue Apr 24, 2023

Add ctests for #4847 via a python script calling the CLI on a ruby/py…

44dade4

…thon file

jmarrec added a commit that referenced this issue Apr 24, 2023

Workaround for #4847 - Disable the libopenstudiolib logger since the …

8301544

…ruby shared lib has a duplicated one...

tijcolem closed this as completed in #4852 Apr 25, 2023

tijcolem added a commit that referenced this issue Apr 25, 2023

Merge pull request #4852 from NREL/4847_CLI_RubyLogger

e62d497

Fix #4847 - OpenStudio logging behaves differently on Windows/Linux

shorowit reopened this Jan 5, 2024

shorowit mentioned this issue Jan 5, 2024

Suppress warnings when running tests NREL/OpenStudio-HPXML#1585

Merged

7 tasks

DavidGoldwasser added the component - logs and warnings label Jan 29, 2024

jmarrec changed the title ~~OpenStudio logging behaves differently on Windows/Linux~~ OpenStudio logging singleton issues (especially on Windows) when using interpreted bindings (ruby measures) Jan 29, 2024

jmarrec assigned kbenne Jan 29, 2024

kbenne added a commit that referenced this issue Mar 14, 2024

Rename LoggerSingleton to LoggerImpl

5508f9f

ref #4847

jmarrec pushed a commit that referenced this issue Mar 14, 2024

Rename LoggerSingleton to LoggerImpl

7f2989b

ref #4847

DavidGoldwasser added this to the OpenStudio SDK 3.8.0 milestone Mar 21, 2024

jmarrec pushed a commit that referenced this issue Mar 22, 2024

Rename LoggerSingleton to LoggerImpl

69c474b

ref #4847

jmarrec added a commit that referenced this issue Mar 22, 2024

Remove poor man's hack for #4847

c162c04

shorowit closed this as completed Apr 30, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

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

shorowit commented Mar 30, 2023

jmarrec commented Apr 4, 2023

jmarrec commented Apr 4, 2023

jmarrec commented Apr 4, 2023

jmarrec commented Apr 4, 2023 •

edited

Loading

jmarrec commented Apr 4, 2023 •

edited

Loading

jmarrec commented Apr 4, 2023

shorowit commented Jan 5, 2024 •

edited

Loading

shorowit commented Jan 12, 2024 •

edited

Loading

jmarrec commented Jan 15, 2024

kbenne commented Feb 16, 2024

shorowit commented Feb 19, 2024

kbenne commented Mar 28, 2024

shorowit commented Apr 30, 2024

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

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

Comments

shorowit commented Mar 30, 2023

Issue overview

Expected Behavior

Steps to Reproduce

Details

Environment

jmarrec commented Apr 4, 2023

jmarrec commented Apr 4, 2023

jmarrec commented Apr 4, 2023

jmarrec commented Apr 4, 2023 • edited Loading

jmarrec commented Apr 4, 2023 • edited Loading

jmarrec commented Apr 4, 2023

shorowit commented Jan 5, 2024 • edited Loading

shorowit commented Jan 12, 2024 • edited Loading

jmarrec commented Jan 15, 2024

kbenne commented Feb 16, 2024

shorowit commented Feb 19, 2024

kbenne commented Mar 28, 2024

shorowit commented Apr 30, 2024

jmarrec commented Apr 4, 2023 •

edited

Loading

jmarrec commented Apr 4, 2023 •

edited

Loading

shorowit commented Jan 5, 2024 •

edited

Loading

shorowit commented Jan 12, 2024 •

edited

Loading