Repository: NREL/OpenStudio (language: python)

Issue:
OpenStudio logging singleton issues (especially on Windows) when using interpreted bindings (ruby measures)
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.

```patch
--- 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.

```patch
--- 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](https://github.com/NREL/OpenStudio-HPXML/blob/4f39a733f647d7b7366b176bc66925845b91de20/HPXMLtoOpenStudio/resources/meta_measure.rb#L15) 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
OpenStudio logging singleton issues (especially on Windows) when using interpreted bindings (ruby measures)
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.

```patch
--- 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.

```patch
--- 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](https://github.com/NREL/OpenStudio-HPXML/blob/4f39a733f647d7b7366b176bc66925845b91de20/HPXMLtoOpenStudio/resources/meta_measure.rb#L15) 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
OpenStudio logging singleton issues (especially on Windows) when using interpreted bindings (ruby measures)
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.

```patch
--- 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.

```patch
--- 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](https://github.com/NREL/OpenStudio-HPXML/blob/4f39a733f647d7b7366b176bc66925845b91de20/HPXMLtoOpenStudio/resources/meta_measure.rb#L15) 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


Discussion / hints:
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:

```ruby
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)
```
Well actually I can reproduce using only the compact_ruby_only.osw we have in source.

```shell
(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
```

```shell
$ 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
https://github.com/NREL/OpenStudio/blob/33626993b6315a614eb67de7b158bf4e5fb384d9/ruby/engine/openstudio_cli.rb#L49-L56
Ok, here is a proper MCVE:

```ruby
$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:

```shell
$ 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:

```shell
$ 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
```
And here we are... We broke something during the `labs` work

```shell
$ 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: https://github.com/NREL/OpenStudio/commit/50f6c0378ce1e5e4e48c525d7d1e2e80fd6adcb2 . 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.
On windows, if here I modify this line: https://github.com/NREL/OpenStudio/blob/33626993b6315a614eb67de7b158bf4e5fb384d9/src/cli/main.cpp#L299

to be

```diff
+   // 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

```shell
$ 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
```
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:

```ruby
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)
```
Well actually I can reproduce using only the compact_ruby_only.osw we have in source.

```shell
(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
```

```shell
$ 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
https://github.com/NREL/OpenStudio/blob/33626993b6315a614eb67de7b158bf4e5fb384d9/ruby/engine/openstudio_cli.rb#L49-L56
Ok, here is a proper MCVE:

```ruby
$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:

```shell
$ 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:

```shell
$ 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
```
And here we are... We broke something during the `labs` work

```shell
$ 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: https://github.com/NREL/OpenStudio/commit/50f6c0378ce1e5e4e48c525d7d1e2e80fd6adcb2 . 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.
On windows, if here I modify this line: https://github.com/NREL/OpenStudio/blob/33626993b6315a614eb67de7b158bf4e5fb384d9/src/cli/main.cpp#L299

to be

```diff
+   // 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

```shell
$ 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
```
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:

```ruby
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)
```
Well actually I can reproduce using only the compact_ruby_only.osw we have in source.

```shell
(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
```

```shell
$ 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
https://github.com/NREL/OpenStudio/blob/33626993b6315a614eb67de7b158bf4e5fb384d9/ruby/engine/openstudio_cli.rb#L49-L56
Ok, here is a proper MCVE:

```ruby
$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:

```shell
$ 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:

```shell
$ 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
```
And here we are... We broke something during the `labs` work

```shell
$ 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: https://github.com/NREL/OpenStudio/commit/50f6c0378ce1e5e4e48c525d7d1e2e80fd6adcb2 . 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.
On windows, if here I modify this line: https://github.com/NREL/OpenStudio/blob/33626993b6315a614eb67de7b158bf4e5fb384d9/src/cli/main.cpp#L299

to be

```diff
+   // 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

```shell
$ 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
```

Fix patch:
diff --git a/src/cli/CMakeLists.txt b/src/cli/CMakeLists.txt
index 21edfa17ec9..970157554bd 100644
--- a/src/cli/CMakeLists.txt
+++ b/src/cli/CMakeLists.txt
@@ -230,6 +230,18 @@ if(BUILD_TESTING)
   )
   set_tests_properties(OpenStudioCLI.Labs.Run_RubyPython PROPERTIES RESOURCE_LOCK "compact_osw")
 
+  add_test(NAME OpenStudioCLI.test_logger_rb
+    COMMAND ${Python_EXECUTABLE} "${CMAKE_CURRENT_SOURCE_DIR}/test/run_test_logger.py" $<TARGET_FILE:openstudio> ${CMAKE_CURRENT_SOURCE_DIR}/test/logger_test.rb
+  )
+
+  add_test(NAME OpenStudioCLI.Labs.test_logger_rb
+    COMMAND ${Python_EXECUTABLE} "${CMAKE_CURRENT_SOURCE_DIR}/test/run_test_logger.py" $<TARGET_FILE:openstudio> --labs ${CMAKE_CURRENT_SOURCE_DIR}/test/logger_test.rb
+  )
+
+  add_test(NAME OpenStudioCLI.Labs.test_logger_py
+    COMMAND ${Python_EXECUTABLE} "${CMAKE_CURRENT_SOURCE_DIR}/test/run_test_logger.py" $<TARGET_FILE:openstudio> --labs ${CMAKE_CURRENT_SOURCE_DIR}/test/logger_test.py
+  )
+
 
   # ============ #4856 - Forward a Path properly no matter the slashes employed ============
 
diff --git a/src/cli/main.cpp b/src/cli/main.cpp
index 74be9e37cb1..b3d87ac5700 100644
--- a/src/cli/main.cpp
+++ b/src/cli/main.cpp
@@ -4,6 +4,7 @@
 #include "../workflow/OSWorkflow.hpp"
 #include "../utilities/core/ASCIIStrings.hpp"
 #include "../utilities/core/Logger.hpp"
+#include "../utilities/core/StringStreamLogSink.hpp"
 #include "../utilities/bcl/BCLMeasure.hpp"
 #include "../measure/ModelMeasure.hpp"
 #include "../measure/EnergyPlusMeasure.hpp"
@@ -306,6 +307,14 @@ int main(int argc, char* argv[]) {
     // fmt::print("gemPathDirs={}\n", fmt::join(gemPathDirs, ","));
     // fmt::print("gemHomeDir={}\n", gemHomeDir);
   } else {
+#if defined _WIN32
+    // Poor man's hack #4847
+    // Disable this logger, we have a duplicate in the ruby shared lib
+    openstudio::Logger::instance().standardOutLogger().disable();
+    openstudio::Logger::instance().standardErrLogger().disable();
+    // Avoid getting some messages during getOpenStudioModule() when we locate the DLL
+    openstudio::StringStreamLogSink sink;
+#endif
     result = openstudio::rubyCLI(rubyEngine);
   }
 


Test patch:
diff --git a/src/cli/test/logger_test.py b/src/cli/test/logger_test.py
new file mode 100644
index 00000000000..ffa0ccdf601
--- /dev/null
+++ b/src/cli/test/logger_test.py
@@ -0,0 +1,23 @@
+import logging
+import openstudio
+import sys
+
+# Root logger
+logger = logging.getLogger()
+logger.setLevel(logging.WARNING)
+
+formatter = logging.Formatter('LOGGER - %(message)s')
+handler = logging.StreamHandler(sys.stdout)
+handler.setLevel(logging.WARNING)
+handler.setFormatter(formatter)
+logger.addHandler(handler)
+
+openstudio.Logger_instance().standardOutLogger().setLogLevel(openstudio.Error)
+
+logger.info("STDOUT Info")
+logger.warning("STDOUT Warn")
+logger.error("STDOUT Error")
+
+openstudio.logFree(openstudio.Info, "test", "Info")
+openstudio.logFree(openstudio.Warn, "test", "Warn")
+openstudio.logFree(openstudio.Error, "test", "Error")
diff --git a/src/cli/test/logger_test.rb b/src/cli/test/logger_test.rb
new file mode 100644
index 00000000000..efbbc25247f
--- /dev/null
+++ b/src/cli/test/logger_test.rb
@@ -0,0 +1,15 @@
+$logger = Logger.new(STDOUT)
+$logger.level = Logger::WARN
+$logger.formatter = proc do |severity, datetime, progname, msg|
+   "LOGGER - #{msg}\n"
+end
+
+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")
diff --git a/src/cli/test/run_test_logger.py b/src/cli/test/run_test_logger.py
new file mode 100644
index 00000000000..141b02259dc
--- /dev/null
+++ b/src/cli/test/run_test_logger.py
@@ -0,0 +1,58 @@
+import argparse
+from pathlib import Path
+import subprocess
+
+
+def validate_file(arg):
+    if (filepath := Path(arg)).is_file():
+        return filepath
+    else:
+        raise FileNotFoundError(arg)
+
+if __name__ == "__main__":
+
+    parser = argparse.ArgumentParser(description="Run a logger test.")
+    parser.add_argument(
+        "os_cli_path", type=validate_file, help="Path to the OS CLI"
+    )
+    parser.add_argument('--labs', action='store_true')
+    parser.add_argument(
+        "logger_file", type=validate_file, help="Path to the logger test file to run"
+    )
+    args = parser.parse_args()
+    print(args)
+
+    command = [str(args.os_cli_path)]
+    if args.labs:
+        command.append("labs")
+    if (ext := args.logger_file.suffix) == '.py':
+        if not args.labs:
+            raise ValueError("When supplying a .py file, you must pass --labs")
+        command.append("execute_python_script")
+    elif ext == '.rb':
+        command.append("execute_ruby_script")
+    else:
+        raise ValueError(f"logger_file should have a .rb or .py extension, not {ext}")
+
+    command.append(str(args.logger_file))
+    print(f"Running: {' '.join(command)}")
+    r = subprocess.check_output(command, encoding='utf-8')
+    lines = r.splitlines()
+
+    # Pop the labs box
+    i_warn = 0
+    for i, line in enumerate(lines):
+        if "The `labs` command is experimental - Do not use in production" in line:
+            i_warn = i
+            break
+    lines = lines[:(i_warn - 1)] + lines[(i_warn + 2):]
+
+    for i, line in enumerate(lines):
+        print(i, line)
+
+    if (n := len(lines)) != 3:
+        raise IOError(f"Expected 3 lines, got {n}")
+
+    # Ruby when called this way has the openstudio logger messages first instead of last, so just sort
+    lines.sort()
+    assert lines == ['LOGGER - STDOUT Error', 'LOGGER - STDOUT Warn', '[test] <1> Error']