[core] Debug logging facelift (#2060)

* route 'Loading script...' messages through the debug logging framework
  * they are now controllable via debugfilter. to turn off, add this to your dfhack.init file: debugfilter set Warning core script
* clarify debug logging docs
* prevent DEBUG messages from being compiled out of the binary
* recolor INFO messages so they blend into existing console output
* add configuration interface for log message header elements so they are individually configurable. all default to off

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<std::string>& 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());

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));
+
+    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);
-    auto ms = std::chrono::duration_cast<std::chrono::milliseconds>(now.time_since_epoch()) % 1000;
         // 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));
+                             "%T", localtime_r(&now_c, &local));
-    *this << (sz > 0 ? buffer : "HH:MM:SS.")
+        *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<std::chrono::milliseconds>(
+                    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
+        *this << '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__
+    if (config.plugin) {
-        // and __LINE__ passed from the macro if that would be preferred prefix.
+        has_header = true;
-        << ':' << cat.plugin() << ':' << cat.category() << ": ";
+        *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 << ' ';
+    }
 }
 
 

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
+ * Light weight wrappers for runtime debug output filtering. The idea is to add
- * little as possible code compared to debug output without filtering. The
+ * 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
+ * fast path when output is disabled. However, if output is enabled then
- * output is enabled then runtime code will jump to debug printing function
+ * parameters are evaluated and the printing function is called. The macro setup
- * calls. The macro setup code will also print standardized leading part of
+ * code will also print a standard header for each log message, including
- * debug string including time stamp, plugin name and debug category name.
+ * 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
+ * The debug print filtering levels can be changed using a debugger. The
- * gdb example would automatically setup core/init and core/render to trace
+ * following gdb example will automatically setup core/init and core/render to
- * level when SDL_init is called.
+ * 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.
  *

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<void (signalType, DebugCategory&)>;
 
@@ -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

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 <filter id> [<filter id> ...]\n"
     "    Enable filters matching space separated list of ids from 'filter'.\n"
+    "  debugfilter header [enable] | [disable] [<element> ...]\n"
+    "    Control which header metadata is shown along with each log message.\n"
     "  debugfilter help [<subcommand>]\n"
     "    Show detailed help for a command or this help.\n";
 static const char* const commandCategory =
     "  category [<plugin regex> [<category regex>]]\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"
+    "    expression is used to match the category and the second is used\n"
-    "    plugin name.\n";
+    "    to match the plugin name.\n";
 static const char* const commandSet =
     "  set [persistent] <level> [<plugin regex> [<category regex>]]\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] [<element> ...]\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 [<subcommand>]\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<std::string>& 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 &param = 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}},
 };