LogDebug(): implement module-based debug logging.

Now most DEBUG messages are *not* printed even when "-d" is in use, but
the specific debug module has to be enabled on the command line. For
example to enable all log modules, run:

cf-agent -d --log-modules=all

Changelog: commit

cf-agent/cf-agent.c

@@ -186,6 +186,8 @@ static const struct option OPTIONS[] =
     {"color", optional_argument, 0, 'C'},
     {"no-extensions", no_argument, 0, 'E'},
     {"timestamp", no_argument, 0, 'l'},
+    /* Only long option for the rest */
+    {"log-modules", required_argument, 0, 0},
     {NULL, 0, 0, '\0'}
 };
 
@@ -210,6 +212,7 @@ static const char *const HINTS[] =
     "Enable colorized output. Possible values: 'always', 'auto', 'never'. If option is used, the default value is 'auto'",
     "Disable extension loading (used while upgrading)",
     "Log timestamps on each line of log output",
+    "Enable even more detailed debug logging for specific areas of the implementation. Use together with '-d'. Use --log-modules=help for a list of available modules",
     NULL
 };
 
@@ -306,8 +309,9 @@ static GenericAgentConfig *CheckOpts(int argc, char **argv)
     char **argv_new = TranslateOldBootstrapOptionsConcatenated(argc_new, argv_tmp);
     FreeFixedStringArray(argc_new, argv_tmp);
 
+    int longopt_idx;
     while ((c = getopt_long(argc_new, argv_new, "tdvnKIf:w:D:N:VxMB:b:hC::ElT::",
-                            OPTIONS, NULL))
+                            OPTIONS, &longopt_idx))
            != -1)
     {
         switch (c)
@@ -517,6 +521,19 @@ static GenericAgentConfig *CheckOpts(int argc, char **argv)
 
             break;
 
+        /* long options only */
+        case 0:
+
+            if (strcmp(OPTIONS[longopt_idx].name, "log-modules") == 0)
+            {
+                bool ret = LogEnableModulesFromString(optarg);
+                if (!ret)
+                {
+                    exit(EXIT_FAILURE);
+                }
+            }
+            break;
+
         default:
             {
                 Writer *w = FileWriter(stdout);

cf-promises/cf-promises.c

@@ -86,6 +86,8 @@ static const struct option OPTIONS[] =
     {"color", optional_argument, 0, 'C'},
     {"tag-release", required_argument, 0, 'T'},
     {"timestamp", no_argument, 0, 'l'},
+    /* Only long option for the rest */
+    {"log-modules", required_argument, 0, 0},
     {NULL, 0, 0, '\0'}
 };
 
@@ -113,6 +115,7 @@ static const char *const HINTS[] =
     "Enable colorized output. Possible values: 'always', 'auto', 'never'. If option is used, the default value is 'auto'",
     "Tag a directory with promises.cf with cf_promises_validated and cf_promises_release_id",
     "Log timestamps on each line of log output",
+    "Enable even more detailed debug logging for specific areas of the implementation. Use together with '-d'. Use --log-modules=help for a list of available modules",
     NULL
 };
 
@@ -233,8 +236,9 @@ GenericAgentConfig *CheckOpts(int argc, char **argv)
     GenericAgentConfig *config = GenericAgentConfigNewDefault(AGENT_TYPE_COMMON, GetTTYInteractive());
     config->tag_release_dir = NULL;
 
+    int longopt_idx;
     while ((c = getopt_long(argc, argv, "dvnIw:f:D:N:VSrxMb:i:p:s:cg:hW:C::T:l",
-                            OPTIONS, NULL))
+                            OPTIONS, &longopt_idx))
            != -1)
     {
         switch (c)
@@ -440,6 +444,19 @@ GenericAgentConfig *CheckOpts(int argc, char **argv)
             LoggingEnableTimestamps(true);
             break;
 
+        /* long options only */
+        case 0:
+
+            if (strcmp(OPTIONS[longopt_idx].name, "log-modules") == 0)
+            {
+                bool ret = LogEnableModulesFromString(optarg);
+                if (!ret)
+                {
+                    exit(EXIT_FAILURE);
+                }
+            }
+            break;
+
         default:
         {
             Writer *w = FileWriter(stdout);

cf-runagent/cf-runagent.c

@@ -110,7 +110,8 @@ static const struct option OPTIONS[] =
     {"timeout", required_argument, 0, 't'},
     {"color", optional_argument, 0, 'C'},
     {"timestamp", no_argument, 0, 'l'},
-    /* Only long option for the following! */
+    /* Only long option for the rest */
+    {"log-modules", required_argument, 0, 0},
     {"remote-bundles", required_argument, 0, 0},
     {NULL, 0, 0, '\0'}
 };
@@ -134,6 +135,7 @@ static const char *const HINTS[] =
     "Connection timeout, seconds",
     "Enable colorized output. Possible values: 'always', 'auto', 'never'. If option is used, the default value is 'auto'",
     "Log timestamps on each line of log output",
+    "Enable even more detailed debug logging for specific areas of the implementation. Use together with '-d'. Use --log-modules=help for a list of available modules",
     "Bundles to execute on the remote agent",
     NULL
 };
@@ -387,7 +389,15 @@ static GenericAgentConfig *CheckOpts(int argc, char **argv)
         /* long options only */
         case 0:
 
-            if (strcmp(OPTIONS[longopt_idx].name, "remote-bundles") == 0)
+            if (strcmp(OPTIONS[longopt_idx].name, "log-modules") == 0)
+            {
+                bool ret = LogEnableModulesFromString(optarg);
+                if (!ret)
+                {
+                    exit(EXIT_FAILURE);
+                }
+            }
+            else if (strcmp(OPTIONS[longopt_idx].name, "remote-bundles") == 0)
             {
                 size_t len = strlen(REMOTEBUNDLES);
                 StrCatDelim(REMOTEBUNDLES, sizeof(REMOTEBUNDLES), &len,

libutils/logging.c

@@ -27,6 +27,7 @@
 #include <string_lib.h>
 #include <misc_lib.h>
 
+
 char VPREFIX[1024] = ""; /* GLOBAL_C */
 
 static char AgentType[80] = "generic";
@@ -310,6 +311,148 @@ void Log(LogLevel level, const char *fmt, ...)
     va_end(ap);
 }
 
+
+
+static bool module_is_enabled[LOG_MOD_MAX];
+static const char *log_modules[LOG_MOD_MAX] =
+{
+    "",
+    "evalctx",
+    "expand",
+    "iterngn",
+    "parser",
+    "vartable",
+    "vars",
+};
+
+static enum LogModule LogModuleFromString(const char *s)
+{
+    for (enum LogModule i = 0; i < LOG_MOD_MAX; i++)
+    {
+        if (strcmp(log_modules[i], s) == 0)
+        {
+            return i;
+        }
+    }
+
+    return LOG_MOD_NONE;
+}
+
+void LogEnableModule(enum LogModule mod)
+{
+    assert(mod < LOG_MOD_MAX);
+
+    module_is_enabled[mod] = true;
+}
+
+void LogModuleHelp(void)
+{
+    printf("\n--log-modules accepts a comma separated list of one or more of the following:\n\n");
+    printf("    help\n");
+    printf("    all\n");
+    for (enum LogModule i = LOG_MOD_NONE + 1;  i < LOG_MOD_MAX;  i++)
+    {
+        printf("    %s\n", log_modules[i]);
+    }
+    printf("\n");
+}
+
+/**
+ * Parse a string of modules, and enable the relevant DEBUG logging modules.
+ * Example strings:
+ *
+ *   all         : enables all debug modules
+ *   help        : enables nothing, but prints a help message
+ *   iterctx     : enables the "iterctx" debug logging module
+ *   iterctx,vars: enables the 2 debug modules, "iterctx" and "vars"
+ *
+ * @NOTE modifies string #s but restores it before returning.
+ */
+bool LogEnableModulesFromString(char *s)
+{
+    bool retval = true;
+
+    const char *token = s;
+    char saved_sep = ',';                     /* any non-NULL value will do */
+    while (saved_sep != '\0' && retval != false)
+    {
+        char *next_token = strchrnul(token, ',');
+        saved_sep        = *next_token;
+        *next_token      = '\0';                      /* modify parameter s */
+        size_t token_len = next_token - token;
+
+        if (strcmp(token, "help") == 0)
+        {
+            LogModuleHelp();
+            retval = false;                                   /* early exit */
+        }
+        else if (strcmp(token, "all") == 0)
+        {
+            for (enum LogModule j = LOG_MOD_NONE + 1; j < LOG_MOD_MAX; j++)
+            {
+                LogEnableModule(j);
+            }
+        }
+        else
+        {
+            enum LogModule mod = LogModuleFromString(token);
+
+            assert(mod < LOG_MOD_MAX);
+            if (mod == LOG_MOD_NONE)
+            {
+                Log(LOG_LEVEL_WARNING,
+                    "Unknown debug logging module '%*s'",
+                    (int) token_len, token);
+            }
+            else
+            {
+                LogEnableModule(mod);
+            }
+        }
+
+
+        *next_token = saved_sep;            /* restore modified parameter s */
+        next_token++;                       /* bypass comma */
+        token = next_token;
+    }
+
+    return retval;
+}
+
+bool LogModuleEnabled(enum LogModule mod)
+{
+    assert(mod > LOG_MOD_NONE);
+    assert(mod < LOG_MOD_MAX);
+
+    if (module_is_enabled[mod])
+    {
+        return true;
+    }
+    else
+    {
+        return false;
+    }
+}
+
+void LogDebug(enum LogModule mod, const char *fmt, ...)
+{
+    assert(mod < LOG_MOD_MAX);
+
+    /* Did we forget any entry in log_modules? Should be a static assert. */
+    assert(sizeof(log_modules) / sizeof(log_modules[0]) == LOG_MOD_MAX);
+
+    if (LogModuleEnabled(mod))
+    {
+        va_list ap;
+        va_start(ap, fmt);
+        VLog(LOG_LEVEL_DEBUG, fmt, ap);
+        va_end(ap);
+        /* VLog(LOG_LEVEL_DEBUG, "%s: ...", */
+        /*      debug_modules_description[mod_order], ...); */
+    }
+}
+
+
 void LogSetGlobalLevel(LogLevel level)
 {
     global_level = level;

libutils/logging.h

@@ -22,15 +22,19 @@
   included file COSL.txt.
 */
 
+
 #ifndef CFENGINE_LOGGING_H
 #define CFENGINE_LOGGING_H
 
+
 #include <platform.h>
 #include <compiler.h>
 
+
 // Does not include timezone, since it is hard to match on Windows.
 #define LOGGING_TIMESTAMP_REGEX "^20[0-9][0-9]-[01][0-9]-[0-3][0-9]T[0-2][0-9]:[0-5][0-9]:[0-5][0-9]"
 
+
 typedef enum
 {
     LOG_LEVEL_NOTHING = -1,
@@ -43,8 +47,27 @@ typedef enum
     LOG_LEVEL_DEBUG
 } LogLevel;
 
+
+/**
+ *  Enum used as a parameter in LogDebug(), used to print even more detailed
+ *  info than Log(LOG_LEVEL_DEBUG).
+ */
+enum LogModule
+{
+    LOG_MOD_NONE = 0,                         /* DEFAULT DEBUG LOGGING */
+    LOG_MOD_EVALCTX,                          /* evaluator */
+    LOG_MOD_EXPAND,                           /* variables expansion */
+    LOG_MOD_ITERNGN,                          /* evaluator iteration engine */
+    LOG_MOD_PARSER,                           /* yacc */
+    LOG_MOD_VARTABLE,                         /* variables tables */
+    LOG_MOD_VARS,                             /* variables promise */
+    LOG_MOD_MAX
+};
+
+
 #include <logging_priv.h>
 
+
 typedef struct
 {
     LogLevel log_level;
@@ -68,6 +91,7 @@ bool LoggingFormatTimestamp(char dest[64], size_t n, struct tm *timestamp);
 LoggingContext *GetCurrentThreadContext(void);
 
 void Log(LogLevel level, const char *fmt, ...) FUNC_ATTR_PRINTF(2, 3);
+void LogDebug(enum LogModule mod, const char *fmt, ...) FUNC_ATTR_PRINTF(2, 3);
 void LogRaw(LogLevel level, const char *prefix, const void *buf, size_t buflen);
 void VLog(LogLevel level, const char *fmt, va_list ap);
 
@@ -89,4 +113,10 @@ void LogToSystemLog(const char *msg, LogLevel level);
 const char *GetErrorStr(void);
 const char *GetErrorStrFromCode(int error_code);
 
+void LogModuleHelp(void);
+bool LogModuleEnabled(enum LogModule mod);
+void LogEnableModule(enum LogModule mod);
+bool LogEnableModulesFromString(char *s);
+
+
 #endif