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): diff --git a/src/utilities/core/LogSink.cpp b/src/utilities/core/LogSink.cpp index cb1e0923d11..77dac3d60e6 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..e871fe6e072 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 = true); + + 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..dceab417755 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,9 @@ 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: /// private constructor LoggerSingleton(); 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; diff --git a/src/workflow/OSWorkflow.cpp b/src/workflow/OSWorkflow.cpp index a80ba84e060..c67f1b219ac 100644 --- a/src/workflow/OSWorkflow.cpp +++ b/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 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(); + } + + // 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)] + << "> " + // 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) {