diff --git a/library/Core.cpp b/library/Core.cpp index 44c68391e..10f5057f3 100644 --- a/library/Core.cpp +++ b/library/Core.cpp @@ -41,6 +41,7 @@ using namespace std; #include "MemAccess.h" #include "Core.h" #include "DataDefs.h" +#include "Debug.h" #include "Console.h" #include "MiscUtils.h" #include "Module.h" @@ -101,6 +102,9 @@ static bool parseKeySpec(std::string keyspec, int *psym, int *pmod, std::string size_t loadScriptFiles(Core* core, color_ostream& out, const vector& prefix, const std::string& folder); namespace DFHack { + +DBG_DECLARE(core,script,DebugCategory::LINFO); + class MainThread { public: //! MainThread::suspend keeps the main DF thread suspended from Core::Init to @@ -1401,7 +1405,7 @@ command_result Core::runCommand(color_ostream &con, const std::string &first_, v bool Core::loadScriptFile(color_ostream &out, string fname, bool silent) { if(!silent) { - out << "Loading script: " << fname << std::endl; + INFO(script,out) << "Loading script: " << fname << std::endl; cerr << "Loading script: " << fname << std::endl; } ifstream script(fname.c_str()); diff --git a/library/Debug.cpp b/library/Debug.cpp index aa0cf8cdf..7ac981d30 100644 --- a/library/Debug.cpp +++ b/library/Debug.cpp @@ -80,17 +80,17 @@ static color_value selectColor(const DebugCategory::level msgLevel) { switch(msgLevel) { case DebugCategory::LTRACE: - return COLOR_GREY; + return COLOR_BROWN; case DebugCategory::LDEBUG: return COLOR_LIGHTBLUE; - case DebugCategory::LINFO: - return COLOR_CYAN; case DebugCategory::LWARNING: return COLOR_YELLOW; case DebugCategory::LERROR: return COLOR_LIGHTRED; + case DebugCategory::LINFO: + default: + return COLOR_RESET; } - return COLOR_WHITE; } #if __GNUC__ @@ -113,31 +113,56 @@ DebugCategory::ostream_proxy_prefix::ostream_proxy_prefix( const DebugCategory::level msgLevel) : color_ostream_proxy(target) { + DebugManager &dm = DebugManager::getInstance(); + const DebugManager::HeaderConfig &config = dm.getHeaderConfig(); + color(selectColor(msgLevel)); - auto now = std::chrono::system_clock::now(); - tm local{}; - //! \todo c++ 2020 will have std::chrono::to_stream(fmt, system_clock::now()) - //! but none implements it yet. - std::time_t now_c = std::chrono::system_clock::to_time_t(now); - auto ms = std::chrono::duration_cast(now.time_since_epoch()) % 1000; - // Output time in format %02H:%02M:%02S.%03ms + + bool has_header = false; + if (config.timestamp) { + has_header = true; + auto now = std::chrono::system_clock::now(); + tm local{}; + //! \todo c++ 2020 will have std::chrono::to_stream(fmt, system_clock::now()) + //! but none implements it yet. + std::time_t now_c = std::chrono::system_clock::to_time_t(now); + // Output time in format %02H:%02M:%02S.%03ms #if __GNUC__ < 5 - // Fallback for gcc 4 - char buffer[32]; - size_t sz = strftime(buffer, sizeof(buffer)/sizeof(buffer[0]), - "%T.", localtime_r(&now_c, &local)); - *this << (sz > 0 ? buffer : "HH:MM:SS.") + // Fallback for gcc 4 + char buffer[32]; + size_t sz = strftime(buffer, sizeof(buffer)/sizeof(buffer[0]), + "%T", localtime_r(&now_c, &local)); + *this << (sz > 0 ? buffer : "HH:MM:SS"); #else - *this << std::put_time(localtime_r(&now_c, &local),"%T.") + *this << std::put_time(localtime_r(&now_c, &local),"%T"); #endif - << std::setfill('0') << std::setw(3) << ms.count() + if (config.timestamp_ms) { + auto ms = std::chrono::duration_cast( + now.time_since_epoch()) % 1000; + *this << '.' << std::setfill('0') << std::setw(3) << ms.count(); + } + *this << ':'; + } + if (config.thread_id) { + has_header = true; // Thread id is allocated in the thread creation order to a thread_local // variable - << ":t" << thread_id - // Output plugin and category names to make it easier to locate where - // the message is coming. It would be easy replaces these with __FILE__ - // and __LINE__ passed from the macro if that would be preferred prefix. - << ':' << cat.plugin() << ':' << cat.category() << ": "; + *this << 't' << thread_id << ':'; + } + if (config.plugin) { + has_header = true; + *this << cat.plugin() << ':'; + } + if (config.category) { + has_header = true; + *this << cat.category() << ':'; + } + // It would be easy to pass __FILE__ and __LINE__ from the logging macros + // and include that information as well, if we want to. + + if (has_header) { + *this << ' '; + } } diff --git a/library/include/Debug.h b/library/include/Debug.h index 976172c8d..63811a51e 100644 --- a/library/include/Debug.h +++ b/library/include/Debug.h @@ -31,17 +31,17 @@ redistribute it freely, subject to the following restrictions: namespace DFHack { /*! \file Debug.h - * Light weight wrappers to runtime debug output filtering. Idea is to add as - * little as possible code compared to debug output without filtering. The + * Light weight wrappers for runtime debug output filtering. The idea is to add + * as little as possible code compared to debug output without filtering. The * effect is archived using #TRACE, #DEBUG, #INFO, #WARN and #ERR macros. They * "return" color_ostream object or reference that can be then used normally for * either printf or stream style debug output. * * Internally macros do inline filtering check which allows compiler to have a - * fast path without debug output only checking unlikely condition. But if - * output is enabled then runtime code will jump to debug printing function - * calls. The macro setup code will also print standardized leading part of - * debug string including time stamp, plugin name and debug category name. + * fast path when output is disabled. However, if output is enabled then + * parameters are evaluated and the printing function is called. The macro setup + * code will also print a standard header for each log message, including + * timestamp, plugin name, and category name. * * \code{.cpp} * #include "Debug.h" @@ -60,9 +60,9 @@ namespace DFHack { * } * \endcode * - * The debug print filtering levels can be changed using debugger. Following - * gdb example would automatically setup core/init and core/render to trace - * level when SDL_init is called. + * The debug print filtering levels can be changed using a debugger. The + * following gdb example will automatically setup core/init and core/render to + * trace level when SDL_init is called. * * \code{.unparsed} * break SDL_init @@ -101,8 +101,11 @@ namespace DFHack { //! \} #ifdef NDEBUG -//! Reduce minimum compiled in debug levels if NDEBUG is defined -#define DBG_FILTER DFHack::DebugCategory::LINFO +/*! + * Reduce minimum compiled in debug levels if NDEBUG is defined. This is LDEBUG + * and not LINFO so users can usefully increase logging levels for bug reports. + */ +#define DBG_FILTER DFHack::DebugCategory::LDEBUG #else //! Set default compiled in debug levels to include all prints #define DBG_FILTER DFHack::DebugCategory::LTRACE @@ -172,8 +175,7 @@ public: ostream_proxy_prefix(const DebugCategory& cat, color_ostream& target, DebugCategory::level level); - ~ostream_proxy_prefix() - { + ~ostream_proxy_prefix() { flush(); } }; @@ -255,10 +257,10 @@ public: /*! - * Declares a debug category. There must be only a declaration per category. + * Declares a debug category. There must be only one declaration per category. * Declaration should be in same plugin where it is used. If same category name * is used in core and multiple plugins they all are changed with same command - * unless user specifies explicitly plugin name. + * unless user explicitly specifies a plugin name. * * Must be used in one translation unit only. * diff --git a/library/include/DebugManager.h b/library/include/DebugManager.h index fb4c635fb..57de0f279 100644 --- a/library/include/DebugManager.h +++ b/library/include/DebugManager.h @@ -72,6 +72,15 @@ public: CAT_MODIFIED, }; + //! Log message header configuration, controlled via the debug plugin + struct HeaderConfig { + bool timestamp = false; // Hour, minute, and seconds + bool timestamp_ms = false; // only used if timestamp == true + bool thread_id = false; + bool plugin = false; + bool category = false; + }; + //! type to help access signal features like Connection and BlockGuard using categorySignal_t = Signal; @@ -91,6 +100,16 @@ public: return instance; } + // don't bother to protect these with mutexes. we don't want to pay the + // performance cost of locking on every log message, and the consequences + // of race conditions are minimal. + const HeaderConfig & getHeaderConfig() const { + return headerConfig; + } + void setHeaderConfig(const HeaderConfig &config) { + headerConfig = config; + } + //! Prevent copies DebugManager(const DebugManager&) = delete; //! Prevent copies @@ -102,6 +121,8 @@ public: protected: DebugManager() = default; + HeaderConfig headerConfig; + //! Helper for automatic category registering and signaling void registerCategory(DebugCategory &); //! Helper for automatic category unregistering and signaling diff --git a/plugins/debug.cpp b/plugins/debug.cpp index ee35bcdf6..30a5028f8 100644 --- a/plugins/debug.cpp +++ b/plugins/debug.cpp @@ -44,6 +44,7 @@ DBG_DECLARE(debug,filter); DBG_DECLARE(debug,init); DBG_DECLARE(debug,command); DBG_DECLARE(debug,ui); +DBG_DECLARE(debug,example,DebugCategory::LINFO); } namespace serialization { @@ -118,14 +119,16 @@ static const char* const commandHelp = " Disable filters matching space separated list of ids from 'filter'.\n" " debugfilter enable [ ...]\n" " Enable filters matching space separated list of ids from 'filter'.\n" + " debugfilter header [enable] | [disable] [ ...]\n" + " Control which header metadata is shown along with each log message.\n" " debugfilter help []\n" " Show detailed help for a command or this help.\n"; static const char* const commandCategory = " category [ []]\n" " List categories with optional filters. Parameters are passed to\n" " std::regex to limit which once are shown. The first regular\n" - " expression is used to match category and the second is used match\n" - " plugin name.\n"; + " expression is used to match the category and the second is used\n" + " to match the plugin name.\n"; static const char* const commandSet = " set [persistent] [ []]\n" " Set filtering level for matching categories. 'level' must be one of\n" @@ -161,6 +164,12 @@ static const char* const commandEnable = " It will reset any matching category back to the default 'warning'\n" " level or any other still active matching filter level.\n" " 'enable' will print red filters that were already enabled.\n"; +static const char* const commandHeader = + " header [enable] | [disable] [ ...]\n" + " 'header' allows you to customize what metadata is displayed with\n" + " each log message. Run it without parameters to see the list of\n" + " configurable elements. Include an 'enable' or 'disable' keyword to\n" + " change specific elements.\n"; static const char* const commandHelpDetails = " help []\n" " Show help for any of subcommands. Without any parameters it shows\n" @@ -1063,6 +1072,55 @@ static command_result unsetFilter(color_ostream& out, }); } +static const int welement = 16; +static const int wsetting = 12; + +static void listHeaderSetting(color_ostream& out, color_ostream::color_value c, + const char *name, bool val) { + out.color(c); + out << std::setw(welement) << name + << std::setw(wsetting) << (val ? "Enabled" : "Disabled") << '\n'; +} + +static command_result configureHeader(color_ostream& out, + std::vector& parameters) +{ + DebugManager &dm = DebugManager::getInstance(); + DebugManager::HeaderConfig config = dm.getHeaderConfig(); + + const size_t nparams = parameters.size(); + if (nparams >= 2 && + (parameters[1] == "enable" || parameters[1] == "disable")) { + bool val = parameters[1] == "enable" ? true : false; + for (size_t idx = 1; nparams > idx; ++idx) { + const std::string ¶m = parameters[idx]; + if (param == "timestamp") config.timestamp = val; + else if (param == "timestamp_ms") config.timestamp_ms = val; + else if (param == "thread_id") config.thread_id = val; + else if (param == "plugin") config.plugin = val; + else if (param == "category") config.category = val; + } + + dm.setHeaderConfig(config); + } + + out.color(COLOR_GREEN); + out << std::setw(welement) << "Header element" + << std::setw(wsetting) << "Setting" << '\n'; + + listHeaderSetting(out, COLOR_CYAN, "timestamp", config.timestamp); + listHeaderSetting(out, COLOR_LIGHTCYAN, "timestamp_ms", + config.timestamp_ms); + listHeaderSetting(out, COLOR_CYAN, "thread_id", config.thread_id); + listHeaderSetting(out, COLOR_LIGHTCYAN, "plugin", config.plugin); + listHeaderSetting(out, COLOR_CYAN, "category", config.category); + out << std::endl; + + INFO(example, out) << "Example message" << std::endl; + + return CR_OK; +} + using DFHack::debugPlugin::CommandDispatch; static command_result printHelp(color_ostream& out, @@ -1085,6 +1143,7 @@ CommandDispatch::dispatch_t CommandDispatch::dispatch { {"unset", {unsetFilter,commandUnset}}, {"enable", {enableFilter,commandEnable}}, {"disable", {disableFilter,commandDisable}}, + {"header", {configureHeader,commandHeader}}, {"help", {printHelp,commandHelpDetails}}, };