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

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 ============
 

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);
   }
 

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")

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")

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']