From 7e69ddf467cd5811716b2bfdd681ee3da57de16f Mon Sep 17 00:00:00 2001 From: Julien Marrec Date: Tue, 14 Nov 2023 14:37:41 +0100 Subject: [PATCH 1/7] Add ability to customize a LogSink formatter, use that in OSWorkflow for run.log so it looks like the openstudio-workflow-gem --- src/utilities/core/LogSink.cpp | 63 +++++++++++++++++++++++++---- src/utilities/core/LogSink.hpp | 4 ++ src/utilities/core/LogSink_Impl.hpp | 5 +++ src/utilities/core/Logger.cpp | 11 +++++ src/utilities/core/Logger.hpp | 5 +++ src/workflow/OSWorkflow.cpp | 24 +++++++++++ 6 files changed, 105 insertions(+), 7 deletions(-) diff --git a/src/utilities/core/LogSink.cpp b/src/utilities/core/LogSink.cpp index cb1e0923d11..4ec6783745b 100644 --- a/src/utilities/core/LogSink.cpp +++ b/src/utilities/core/LogSink.cpp @@ -7,9 +7,12 @@ #include "LogSink_Impl.hpp" #include "Logger.hpp" +#include "LogMessage.hpp" #include #include +#include +#include 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(new LogSinkBackend())} {} + // Custom severity level formatting function + std::string formatter_severity_upcase(boost::log::value_ref const& logLevel_) { + static constexpr std::array logLevelStrs = {"TRACE", "DEBUG", "INFO", "WARN", "ERROR", "FATAL"}; + LogLevel logLevel = Trace; + if (logLevel_) { + // if (auto logLevel_ = rec[expr::attr("Severity")]) { + logLevel = logLevel_.get(); + } + + return std::string{logLevelStrs[static_cast(logLevel) - static_cast(LogLevel::Trace)]}; + } + + LogSink_Impl::LogSink_Impl() : m_sink{boost::shared_ptr(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("Channel") << "] <" << expr::attr("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("TimeStamp", "%H:%M:%S.%f") << " " + << boost::phoenix::bind(&formatter_severity_upcase, expr::attr("Severity")) << "] " + << "[" << expr::attr("Channel") << "] " << expr::smessage; + } else { + m_formatter = expr::stream << "[" << expr::format_date_time("TimeStamp", "%H:%M:%S.%f") << " " + << boost::phoenix::bind(&formatter_severity_upcase, expr::attr("Severity")) << "] " << expr::smessage; + } + + } else { + m_formatter = expr::stream << "[" << expr::attr("Channel") << "] <" << expr::attr("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("Channel") << "] <" << expr::attr("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 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 diff --git a/src/utilities/core/LogSink.hpp b/src/utilities/core/LogSink.hpp index 0a1d5c1c623..936f5f021c9 100644 --- a/src/utilities/core/LogSink.hpp +++ b/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 = false); + + void setFormatter(const boost::log::formatter& fmter); + protected: friend class LoggerSingleton; diff --git a/src/utilities/core/LogSink_Impl.hpp b/src/utilities/core/LogSink_Impl.hpp index b7afbe24147..16e671ea984 100644 --- a/src/utilities/core/LogSink_Impl.hpp +++ b/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 m_sink; + boost::log::formatter m_formatter; }; } // namespace detail diff --git a/src/utilities/core/Logger.cpp b/src/utilities/core/Logger.cpp index ce46966ece2..4967ebfb934 100644 --- a/src/utilities/core/Logger.cpp +++ b/src/utilities/core/Logger.cpp @@ -7,6 +7,7 @@ #include #include +#include #include @@ -121,4 +122,14 @@ void LoggerSingleton::removeSink(boost::shared_ptr 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 diff --git a/src/utilities/core/Logger.hpp b/src/utilities/core/Logger.hpp index edfc6f75b63..66091b1cf0b 100644 --- a/src/utilities/core/Logger.hpp +++ b/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 sink); @@ -88,6 +91,8 @@ class UTILITIES_API LoggerSingleton /// removes a sink to the logging core, equivalent to logSink.disable() void removeSink(boost::shared_ptr sink); + void addTimeStampToLogger(); + private: /// private constructor LoggerSingleton(); diff --git a/src/workflow/OSWorkflow.cpp b/src/workflow/OSWorkflow.cpp index a80ba84e060..4c892e0ac4c 100644 --- a/src/workflow/OSWorkflow.cpp +++ b/src/workflow/OSWorkflow.cpp @@ -216,6 +216,28 @@ void OSWorkflow::saveIDFToRootDirIfDebug() { LOG(Info, "Saved IDF as " << savePath); } +void my_formatter(boost::log::record_view const& rec, boost::log::formatting_ostream& strm) { + + // static constexpr std::array logLevelStrs = {"Trace", "Debug", "Info", "Warn", "Error", "Fatal"}; + static constexpr std::array logLevelStrs = {"TRACE", "DEBUG", "INFO", "WARN", "ERROR", "FATAL"}; + + LogLevel logLevel = Trace; + if (auto logLevel_ = boost::log::extract("Severity", rec)) { + logLevel = logLevel_.get(); + } + + strm << "["; + if (auto pt_ = boost::log::extract("TimeStamp", rec)) { + // TimeStamp as [%H:%M:%S.%f] + strm << boost::posix_time::to_simple_string(pt_.get().time_of_day()); + } + strm << logLevelStrs[static_cast(logLevel) - static_cast(LogLevel::Trace)] << "] " + << "[" << boost::log::extract("Channel", rec) + << "] " + // 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 @@ -253,6 +275,8 @@ bool OSWorkflow::run() { openstudio::filesystem::create_directory(runDirPath); } FileLogSink logFile(runDirPath / "run.log"); + const bool include_channel = workflowJSON.runOptions()->debug(); + logFile.useWorkflowGemFormatter(true, include_channel); logFile.setLogLevel(targetLogLevel); if (hasDeletedRunDir) { From 824e6deba163fbbc99c779d975a5dadbc9df8eba Mon Sep 17 00:00:00 2001 From: Julien Marrec Date: Tue, 14 Nov 2023 14:42:23 +0100 Subject: [PATCH 2/7] Use two different ways of setting it: one with full control --- src/workflow/OSWorkflow.cpp | 22 ++++++++++++++++------ 1 file changed, 16 insertions(+), 6 deletions(-) diff --git a/src/workflow/OSWorkflow.cpp b/src/workflow/OSWorkflow.cpp index 4c892e0ac4c..ac0121a6d44 100644 --- a/src/workflow/OSWorkflow.cpp +++ b/src/workflow/OSWorkflow.cpp @@ -229,11 +229,11 @@ void my_formatter(boost::log::record_view const& rec, boost::log::formatting_ost strm << "["; if (auto pt_ = boost::log::extract("TimeStamp", rec)) { // TimeStamp as [%H:%M:%S.%f] - strm << boost::posix_time::to_simple_string(pt_.get().time_of_day()); + strm << "[" << boost::posix_time::to_simple_string(pt_.get().time_of_day()) << "] "; } - strm << logLevelStrs[static_cast(logLevel) - static_cast(LogLevel::Trace)] << "] " - << "[" << boost::log::extract("Channel", rec) - << "] " + strm << "[" << boost::log::extract("Channel", rec) << "] <" // + << logLevelStrs[static_cast(logLevel) - static_cast(LogLevel::Trace)] + << "> " // Finally, the record message << rec[boost::log::expressions::smessage]; } @@ -252,8 +252,13 @@ bool OSWorkflow::run() { if (!m_show_stdout) { openstudio::Logger::instance().standardOutLogger().disable(); - } else if (workflowJSON.runOptions()->debug()) { - openstudio::Logger::instance().standardOutLogger().setLogLevel(targetLogLevel); + } else { + openstudio::Logger::instance().addTimeStampToLogger(); + openstudio::Logger::instance().standardOutLogger().setFormatter(&my_formatter); + + if (workflowJSON.runOptions()->debug()) { + openstudio::Logger::instance().standardOutLogger().setLogLevel(targetLogLevel); + } } // Need to recreate the runDir as fast as possible, so I can direct a file log sink there @@ -275,8 +280,13 @@ bool OSWorkflow::run() { openstudio::filesystem::create_directory(runDirPath); } FileLogSink logFile(runDirPath / "run.log"); +#if 0 + openstudio::Logger::instance().addTimeStampToLogger(); + logFile.setFormatter(&my_formatter); +#else const bool include_channel = workflowJSON.runOptions()->debug(); logFile.useWorkflowGemFormatter(true, include_channel); +#endif logFile.setLogLevel(targetLogLevel); if (hasDeletedRunDir) { From 5bb6e242fa401552c809431413f1a10ba8c69ecf Mon Sep 17 00:00:00 2001 From: Julien Marrec Date: Wed, 15 Nov 2023 17:51:47 +0100 Subject: [PATCH 3/7] Don't swig LogSink::setFormatter --- src/utilities/core/LogSink.hpp | 2 +- src/utilities/core/Logger.i | 1 + 2 files changed, 2 insertions(+), 1 deletion(-) diff --git a/src/utilities/core/LogSink.hpp b/src/utilities/core/LogSink.hpp index 936f5f021c9..e871fe6e072 100644 --- a/src/utilities/core/LogSink.hpp +++ b/src/utilities/core/LogSink.hpp @@ -71,7 +71,7 @@ class UTILITIES_API LogSink /// reset the thread id that messages are filtered by void resetThreadId(); - void useWorkflowGemFormatter(bool use, bool include_channel = false); + void useWorkflowGemFormatter(bool use, bool include_channel = true); void setFormatter(const boost::log::formatter& fmter); diff --git a/src/utilities/core/Logger.i b/src/utilities/core/Logger.i index ecf071b1f13..4178110f9f7 100644 --- a/src/utilities/core/Logger.i +++ b/src/utilities/core/Logger.i @@ -23,6 +23,7 @@ %ignore std::vector::vector(size_type); %ignore std::vector::resize(size_type); %ignore openstudio::LoggerSingleton::loggerFromChannel; +%ignore openstudio::LogSink::setFormatter; %template(LogMessageVector) std::vector; %template(OptionalLogMessage) boost::optional; From 3efa17eac873a909ae5c6dc4189daea943c1e00d Mon Sep 17 00:00:00 2001 From: Julien Marrec Date: Wed, 15 Nov 2023 18:08:46 +0100 Subject: [PATCH 4/7] Cleanup --- src/workflow/OSWorkflow.cpp | 45 +++++++++++++++---------------------- 1 file changed, 18 insertions(+), 27 deletions(-) diff --git a/src/workflow/OSWorkflow.cpp b/src/workflow/OSWorkflow.cpp index ac0121a6d44..34d972bbb70 100644 --- a/src/workflow/OSWorkflow.cpp +++ b/src/workflow/OSWorkflow.cpp @@ -216,21 +216,20 @@ void OSWorkflow::saveIDFToRootDirIfDebug() { LOG(Info, "Saved IDF as " << savePath); } -void my_formatter(boost::log::record_view const& rec, boost::log::formatting_ostream& strm) { +void standardFormatterWithStringSeverity(boost::log::record_view const& rec, boost::log::formatting_ostream& strm) { - // static constexpr std::array logLevelStrs = {"Trace", "Debug", "Info", "Warn", "Error", "Fatal"}; - static constexpr std::array logLevelStrs = {"TRACE", "DEBUG", "INFO", "WARN", "ERROR", "FATAL"}; + static constexpr std::array logLevelStrs = {"Trace", "Debug", "Info", "Warn", "Error", "Fatal"}; + // static constexpr std::array logLevelStrs = {"TRACE", "DEBUG", "INFO", "WARN", "ERROR", "FATAL"}; LogLevel logLevel = Trace; if (auto logLevel_ = boost::log::extract("Severity", rec)) { logLevel = logLevel_.get(); } - strm << "["; - if (auto pt_ = boost::log::extract("TimeStamp", rec)) { - // TimeStamp as [%H:%M:%S.%f] - strm << "[" << boost::posix_time::to_simple_string(pt_.get().time_of_day()) << "] "; - } + // if (auto pt_ = boost::log::extract("TimeStamp", rec)) { + // // TimeStamp as [%H:%M:%S.%f] + // strm << "[" << boost::posix_time::to_simple_string(pt_.get().time_of_day()) << "] "; + // } strm << "[" << boost::log::extract("Channel", rec) << "] <" // << logLevelStrs[static_cast(logLevel) - static_cast(LogLevel::Trace)] << "> " @@ -241,24 +240,19 @@ void my_formatter(boost::log::record_view const& rec, boost::log::formatting_ost 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; } - if (!m_show_stdout) { - openstudio::Logger::instance().standardOutLogger().disable(); - } else { - openstudio::Logger::instance().addTimeStampToLogger(); - openstudio::Logger::instance().standardOutLogger().setFormatter(&my_formatter); + openstudio::Logger::instance().addTimeStampToLogger(); // Needed for run.log formatting + openstudio::Logger::instance().standardOutLogger().setFormatter(&standardFormatterWithStringSeverity); - if (workflowJSON.runOptions()->debug()) { - openstudio::Logger::instance().standardOutLogger().setLogLevel(targetLogLevel); - } + if (!m_show_stdout) { + openstudio::Logger::instance().standardOutLogger().setLogLevel(Error); // Still show errors + } else if (oriLogLevel != targetLogLevel) { + openstudio::Logger::instance().standardOutLogger().setLogLevel(targetLogLevel); } // Need to recreate the runDir as fast as possible, so I can direct a file log sink there @@ -279,14 +273,11 @@ bool OSWorkflow::run() { if (!openstudio::filesystem::is_directory(runDirPath)) { openstudio::filesystem::create_directory(runDirPath); } + FileLogSink logFile(runDirPath / "run.log"); -#if 0 - openstudio::Logger::instance().addTimeStampToLogger(); - logFile.setFormatter(&my_formatter); -#else - const bool include_channel = workflowJSON.runOptions()->debug(); - logFile.useWorkflowGemFormatter(true, include_channel); -#endif + 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) { From 95b6572a6b106244531e6846af9c0695e326a2e8 Mon Sep 17 00:00:00 2001 From: Julien Marrec Date: Wed, 15 Nov 2023 18:14:58 +0100 Subject: [PATCH 5/7] Adjust test that count the log lines now that Ruby and C++ CLI use the same run.log fmt --- src/cli/test/test_with_analysis.py | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/src/cli/test/test_with_analysis.py b/src/cli/test/test_with_analysis.py index 610aac59337..17d4b397033 100644 --- a/src/cli/test/test_with_analysis.py +++ b/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): From 0d09c65374443458b75eca8fb609473b85d26e7d Mon Sep 17 00:00:00 2001 From: Julien Marrec Date: Wed, 15 Nov 2023 18:18:57 +0100 Subject: [PATCH 6/7] Leave a comment for later --- src/workflow/OSWorkflow.cpp | 2 ++ 1 file changed, 2 insertions(+) diff --git a/src/workflow/OSWorkflow.cpp b/src/workflow/OSWorkflow.cpp index 34d972bbb70..c67f1b219ac 100644 --- a/src/workflow/OSWorkflow.cpp +++ b/src/workflow/OSWorkflow.cpp @@ -249,6 +249,8 @@ bool OSWorkflow::run() { 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().setLogLevel(Error); // Still show errors } else if (oriLogLevel != targetLogLevel) { From d7a232f3049172f63f2ae42c0f756562815d55ea Mon Sep 17 00:00:00 2001 From: Julien Marrec Date: Wed, 15 Nov 2023 18:41:15 +0100 Subject: [PATCH 7/7] cppcheck --- src/utilities/core/LogSink.cpp | 14 +++++++------- src/utilities/core/Logger.hpp | 1 + 2 files changed, 8 insertions(+), 7 deletions(-) diff --git a/src/utilities/core/LogSink.cpp b/src/utilities/core/LogSink.cpp index 4ec6783745b..77dac3d60e6 100644 --- a/src/utilities/core/LogSink.cpp +++ b/src/utilities/core/LogSink.cpp @@ -34,13 +34,13 @@ namespace detail { return std::string{logLevelStrs[static_cast(logLevel) - static_cast(LogLevel::Trace)]}; } - LogSink_Impl::LogSink_Impl() : m_sink{boost::shared_ptr(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("Channel") << "] <" << expr::attr("Severity") << "> " << expr::smessage; - } + LogSink_Impl::LogSink_Impl() + : m_sink{boost::shared_ptr(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("Channel") << "] <" << expr::attr("Severity") << "> " << expr::smessage} {} void LogSink_Impl::setFormatter(const boost::log::formatter& fmter) { std::unique_lock l{m_mutex}; diff --git a/src/utilities/core/Logger.hpp b/src/utilities/core/Logger.hpp index 66091b1cf0b..dceab417755 100644 --- a/src/utilities/core/Logger.hpp +++ b/src/utilities/core/Logger.hpp @@ -91,6 +91,7 @@ class UTILITIES_API LoggerSingleton /// removes a sink to the logging core, equivalent to logSink.disable() void removeSink(boost::shared_ptr sink); + // cppcheck-suppress functionConst void addTimeStampToLogger(); private: