Fix #5037 - Adjust log formatters for workflow (stdout + run.log)

src/cli/test/test_with_analysis.py

@@ -117,10 +117,10 @@ class LogLevel(Enum):
 
 
 def _get_search_str(log_level: LogLevel, is_labs: bool) -> str:
-    if is_labs:
-        return f"<{log_level.value}>"
-    else:
-        return f"{log_level.name.upper()}]"
+    # if is_labs:
+    #    return f"<{log_level.value}>"
+    # else:
+    return f"{log_level.name.upper()}]"
 
 
 def _get_lines_with_log_level(run_log: str, log_level: LogLevel, is_labs: bool):

src/utilities/core/LogSink.cpp

@@ -7,9 +7,12 @@
 #include "LogSink_Impl.hpp"
 
 #include "Logger.hpp"
+#include "LogMessage.hpp"
 
 #include <boost/log/support/regex.hpp>
 #include <boost/log/expressions.hpp>
+#include <boost/phoenix/bind.hpp>
+#include <boost/log/support/date_time.hpp>
 
 namespace sinks = boost::log::sinks;
 namespace keywords = boost::log::keywords;
@@ -19,7 +22,50 @@ namespace openstudio {
 
 namespace detail {
 
-  LogSink_Impl::LogSink_Impl() : m_mutex{}, m_threadId{}, m_sink{boost::shared_ptr<LogSinkBackend>(new LogSinkBackend())} {}
+  // Custom severity level formatting function
+  std::string formatter_severity_upcase(boost::log::value_ref<LogLevel> const& logLevel_) {
+    static constexpr std::array<std::string_view, 6> logLevelStrs = {"TRACE", "DEBUG", "INFO", "WARN", "ERROR", "FATAL"};
+    LogLevel logLevel = Trace;
+    if (logLevel_) {
+      // if (auto logLevel_ = rec[expr::attr<LogLevel>("Severity")]) {
+      logLevel = logLevel_.get();
+    }
+
+    return std::string{logLevelStrs[static_cast<size_t>(logLevel) - static_cast<size_t>(LogLevel::Trace)]};
+  }
+
+  LogSink_Impl::LogSink_Impl()
+    : m_sink{boost::shared_ptr<LogSinkBackend>(new LogSinkBackend())},
+      // set formatting, seems like you have to call this after the stream is added
+      // DLM@20110701: would like to format Severity as string but can't figure out how to do it
+      // because you can't overload operator<< for an enum type
+      // this seems to suggest this should work: http://www.edm2.com/0405/enumeration.html
+      m_formatter{expr::stream << "[" << expr::attr<LogChannel>("Channel") << "] <" << expr::attr<LogLevel>("Severity") << "> " << expr::smessage} {}
+
+  void LogSink_Impl::setFormatter(const boost::log::formatter& fmter) {
+    std::unique_lock l{m_mutex};
+    m_formatter = fmter;
+    m_sink->set_formatter(m_formatter);
+  }
+
+  void LogSink_Impl::useWorkflowGemFormatter(bool use, bool include_channel) {
+    std::unique_lock l{m_mutex};
+    if (use) {
+      Logger::instance().addTimeStampToLogger();
+      if (include_channel) {
+        m_formatter = expr::stream << "[" << expr::format_date_time<boost::posix_time::ptime>("TimeStamp", "%H:%M:%S.%f") << " "
+                                   << boost::phoenix::bind(&formatter_severity_upcase, expr::attr<LogLevel>("Severity")) << "] "
+                                   << "[" << expr::attr<LogChannel>("Channel") << "] " << expr::smessage;
+      } else {
+        m_formatter = expr::stream << "[" << expr::format_date_time<boost::posix_time::ptime>("TimeStamp", "%H:%M:%S.%f") << " "
+                                   << boost::phoenix::bind(&formatter_severity_upcase, expr::attr<LogLevel>("Severity")) << "] " << expr::smessage;
+      }
+
+    } else {
+      m_formatter = expr::stream << "[" << expr::attr<LogChannel>("Channel") << "] <" << expr::attr<LogLevel>("Severity") << "> " << expr::smessage;
+    }
+    m_sink->set_formatter(m_formatter);
+  }
 
   bool LogSink_Impl::isEnabled() const {
     return Logger::instance().findSink(m_sink);
@@ -123,12 +169,7 @@ namespace detail {
 
     m_sink->locked_backend()->add_stream(os);
 
-    // set formatting, seems like you have to call this after the stream is added
-    // DLM@20110701: would like to format Severity as string but can't figure out how to do it
-    // because you can't overload operator<< for an enum type
-    // this seems to suggest this should work: http://www.edm2.com/0405/enumeration.html
-    m_sink->set_formatter(expr::stream << "[" << expr::attr<LogChannel>("Channel") << "] <" << expr::attr<LogLevel>("Severity") << "> "
-                                       << expr::smessage);
+    m_sink->set_formatter(m_formatter);
 
     //m_sink->locked_backend()->set_formatter(fmt::stream
     //  << "[" << fmt::attr< LogChannel >("Channel")
@@ -244,4 +285,12 @@ boost::shared_ptr<LogSinkBackend> LogSink::sink() const {
   return m_impl->sink();
 }
 
+void LogSink::useWorkflowGemFormatter(bool use, bool include_channel) {
+  m_impl->useWorkflowGemFormatter(use, include_channel);
+}
+
+void LogSink::setFormatter(const boost::log::formatter& fmter) {
+  m_impl->setFormatter(fmter);
+}
+
 }  // namespace openstudio

src/utilities/core/LogSink.hpp

@@ -71,6 +71,10 @@ class UTILITIES_API LogSink
   /// reset the thread id that messages are filtered by
   void resetThreadId();
 
+  void useWorkflowGemFormatter(bool use, bool include_channel = true);
+
+  void setFormatter(const boost::log::formatter& fmter);
+
  protected:
   friend class LoggerSingleton;
 

src/utilities/core/LogSink_Impl.hpp

@@ -71,6 +71,10 @@ namespace detail {
     /// reset the thread id that messages are filtered by
     void resetThreadId();
 
+    void setFormatter(const boost::log::formatter& fmter);
+
+    void useWorkflowGemFormatter(bool use, bool include_channel = false);
+
    protected:
     friend class openstudio::LogSink;
 
@@ -93,6 +97,7 @@ namespace detail {
     bool m_autoFlush = false;
     std::thread::id m_threadId;
     boost::shared_ptr<LogSinkBackend> m_sink;
+    boost::log::formatter m_formatter;
   };
 
 }  // namespace detail

src/utilities/core/Logger.cpp

@@ -7,6 +7,7 @@
 
 #include <boost/log/common.hpp>
 #include <boost/log/attributes/function.hpp>
+#include <boost/log/attributes/clock.hpp>
 
 #include <boost/core/null_deleter.hpp>
 
@@ -121,4 +122,14 @@ void LoggerSingleton::removeSink(boost::shared_ptr<LogSinkBackend> sink) {
   }
 }
 
+void LoggerSingleton::addTimeStampToLogger() {
+  std::unique_lock l{m_mutex};
+
+  // Add a TimeStamp attribute, same as boost::log::add_common_attributes() would do
+  [[maybe_unused]] auto [it, inserted] = boost::log::core::get()->add_global_attribute("TimeStamp", boost::log::attributes::local_clock{});
+  // if (!use) {
+  //   boost::log::core::get()->remove_global_attribute(it);
+  // }
+}
+
 }  // namespace openstudio

src/utilities/core/Logger.hpp

@@ -51,6 +51,8 @@
 
 namespace openstudio {
 
+class OSWorkflow;
+
 /// convenience function for SWIG, prefer macros in C++
 UTILITIES_API void logFree(LogLevel level, const std::string& channel, const std::string& message);
 
@@ -78,6 +80,7 @@ class UTILITIES_API LoggerSingleton
 
  protected:
   friend class detail::LogSink_Impl;
+  friend class openstudio::OSWorkflow;
 
   /// is the sink found in the logging core
   bool findSink(boost::shared_ptr<LogSinkBackend> sink);
@@ -88,6 +91,9 @@ class UTILITIES_API LoggerSingleton
   /// removes a sink to the logging core, equivalent to logSink.disable()
   void removeSink(boost::shared_ptr<LogSinkBackend> sink);
 
+  // cppcheck-suppress functionConst
+  void addTimeStampToLogger();
+
  private:
   /// private constructor
   LoggerSingleton();

src/utilities/core/Logger.i

@@ -23,6 +23,7 @@
 %ignore std::vector<openstudio::LogMessage>::vector(size_type);
 %ignore std::vector<openstudio::LogMessage>::resize(size_type);
 %ignore openstudio::LoggerSingleton::loggerFromChannel;
+%ignore openstudio::LogSink::setFormatter;
 
 %template(LogMessageVector) std::vector<openstudio::LogMessage>;
 %template(OptionalLogMessage) boost::optional<openstudio::LogMessage>;

src/workflow/OSWorkflow.cpp

@@ -216,21 +216,44 @@ void OSWorkflow::saveIDFToRootDirIfDebug() {
   LOG(Info, "Saved IDF as " << savePath);
 }
 
+void standardFormatterWithStringSeverity(boost::log::record_view const& rec, boost::log::formatting_ostream& strm) {
+
+  static constexpr std::array<std::string_view, 6> logLevelStrs = {"Trace", "Debug", "Info", "Warn", "Error", "Fatal"};
+  // static constexpr std::array<std::string_view, 6> logLevelStrs = {"TRACE", "DEBUG", "INFO", "WARN", "ERROR", "FATAL"};
+
+  LogLevel logLevel = Trace;
+  if (auto logLevel_ = boost::log::extract<LogLevel>("Severity", rec)) {
+    logLevel = logLevel_.get();
+  }
+
+  // if (auto pt_ = boost::log::extract<boost::posix_time::ptime>("TimeStamp", rec)) {
+  //  // TimeStamp as  [%H:%M:%S.%f]
+  //   strm << "[" << boost::posix_time::to_simple_string(pt_.get().time_of_day()) << "] ";
+  // }
+  strm << "[" << boost::log::extract<LogChannel>("Channel", rec) << "] <"  //
+       << logLevelStrs[static_cast<size_t>(logLevel) - static_cast<size_t>(LogLevel::Trace)]
+       << "> "
+       // Finally, the record message
+       << rec[boost::log::expressions::smessage];
+}
+
 bool OSWorkflow::run() {
 
   // If the user passed something like `openstudio --loglevel Trace run --debug -w workflow.osw`, we retain the Trace
-  LogLevel oriLogLevel = Warn;
-  if (auto l_ = openstudio::Logger::instance().standardOutLogger().logLevel()) {
-    oriLogLevel = *l_;
-  }
+  LogLevel oriLogLevel = openstudio::Logger::instance().standardOutLogger().logLevel().value_or(Warn);
   LogLevel targetLogLevel = oriLogLevel;
   if (workflowJSON.runOptions()->debug() && oriLogLevel > Debug) {
     targetLogLevel = Debug;
   }
 
+  openstudio::Logger::instance().addTimeStampToLogger();  // Needed for run.log formatting
+  openstudio::Logger::instance().standardOutLogger().setFormatter(&standardFormatterWithStringSeverity);
+
+  // TODO: ideally we want stdErr logger to always receive Error and Fatal
+  // and stdOut logger should receive all the others. This is definitely doable (cf LogSink::updateFilter) but now is not the time.
   if (!m_show_stdout) {
-    openstudio::Logger::instance().standardOutLogger().disable();
-  } else if (workflowJSON.runOptions()->debug()) {
+    openstudio::Logger::instance().standardOutLogger().setLogLevel(Error);  // Still show errors
+  } else if (oriLogLevel != targetLogLevel) {
     openstudio::Logger::instance().standardOutLogger().setLogLevel(targetLogLevel);
   }
 
@@ -252,7 +275,11 @@ bool OSWorkflow::run() {
   if (!openstudio::filesystem::is_directory(runDirPath)) {
     openstudio::filesystem::create_directory(runDirPath);
   }
+
   FileLogSink logFile(runDirPath / "run.log");
+  constexpr bool use_workflow_gem_fmt = true;
+  constexpr bool include_channel = true;  // or workflowJSON.runOptions()->debug();
+  logFile.useWorkflowGemFormatter(use_workflow_gem_fmt, include_channel);
   logFile.setLogLevel(targetLogLevel);
 
   if (hasDeletedRunDir) {