DEBUG timestamps offer higher precision

https://fedorahosted.org/sssd/ticket/956

Added: --debug-microseconds=0/1
Added: debug_microseconds to sssd.conf

9 files changed, 116 insertions, 21 deletions

diff --git a/src/confdb/confdb.h b/src/confdb/confdb.h
index 4d615761..266e4d27 100644
--- a/src/confdb/confdb.h
+++ b/src/confdb/confdb.h
@@ -51,6 +51,7 @@
 #define CONFDB_SERVICE_COMMAND "command"
 #define CONFDB_SERVICE_DEBUG_LEVEL "debug_level"
 #define CONFDB_SERVICE_DEBUG_TIMESTAMPS "debug_timestamps"
+#define CONFDB_SERVICE_DEBUG_MICROSECONDS "debug_microseconds"
 #define CONFDB_SERVICE_DEBUG_TO_FILES "debug_to_files"
 #define CONFDB_SERVICE_TIMEOUT "timeout"
 #define CONFDB_SERVICE_RECON_RETRIES "reconnection_retries"
diff --git a/src/monitor/monitor.c b/src/monitor/monitor.c
index 4cd1e99d..799b7c69 100644
--- a/src/monitor/monitor.c
+++ b/src/monitor/monitor.c
@@ -62,6 +62,7 @@
 
 int cmdline_debug_level;
 int cmdline_debug_timestamps;
+int cmdline_debug_microseconds;
 
 struct svc_spy;
 
@@ -975,6 +976,17 @@ static int get_service_config(struct mt_ctx *ctx, const char *name,
             }
         }
 
+        if (cmdline_debug_microseconds != SSSDBG_MICROSECONDS_UNRESOLVED) {
+            svc->command = talloc_asprintf_append(
+                svc->command, " --debug-microseconds=%d",
+                cmdline_debug_microseconds
+            );
+            if (!svc->command) {
+                talloc_free(svc);
+                return ENOMEM;
+            }
+        }
+
         if (debug_to_file) {
             svc->command = talloc_strdup_append(
                 svc->command, " --debug-to-files"
@@ -1130,6 +1142,17 @@ static int get_provider_config(struct mt_ctx *ctx, const char *name,
             }
         }
 
+        if (cmdline_debug_microseconds != SSSDBG_MICROSECONDS_UNRESOLVED) {
+            svc->command = talloc_asprintf_append(
+                svc->command, " --debug-microseconds=%d",
+                cmdline_debug_microseconds
+            );
+            if (!svc->command) {
+                talloc_free(svc);
+                return ENOMEM;
+            }
+        }
+
         if (debug_to_file) {
             svc->command = talloc_strdup_append(
                 svc->command, " --debug-to-files"
@@ -2390,11 +2413,12 @@ int main(int argc, const char *argv[])
 
     CONVERT_AND_SET_DEBUG_LEVEL(debug_level);
 
-    /* If the level or timestamps was passed at the command-line, we want
-     * to save it and pass it to the children later.
+    /* If the level, timestamps or microseconds was passed at the command-line,
+     * we want to save it and pass it to the children later.
      */
     cmdline_debug_level = debug_level;
     cmdline_debug_timestamps = debug_timestamps;
+    cmdline_debug_microseconds = debug_microseconds;
 
     if (opt_daemon && opt_interactive) {
         fprintf(stderr, "Option -i|--interactive is not allowed together with -D|--daemon\n");
diff --git a/src/providers/child_common.c b/src/providers/child_common.c
index cde310c3..5920ebc7 100644
--- a/src/providers/child_common.c
+++ b/src/providers/child_common.c
@@ -378,19 +378,25 @@ static errno_t prepare_child_argv(TALLOC_CTX *mem_ctx,
                                   const char *binary,
                                   char ***_argv)
 {
-    uint_t argc = 4; /* program name, debug_level, debug_timestamps and NULL */
+    /*
+     * program name, debug_level, debug_timestamps,
+     * debug_microseconds and NULL
+     */
+    uint_t argc = 5;
     char ** argv;
     errno_t ret = EINVAL;
 
     /* Save the current state in case an interrupt changes it */
     bool child_debug_to_file = debug_to_file;
     bool child_debug_timestamps = debug_timestamps;
+    bool child_debug_microseconds = debug_microseconds;
 
     if (child_debug_to_file) argc++;
 
-    /* program name, debug_level,
-     * debug_to_file, debug_timestamps
-     * and NULL */
+    /*
+     * program name, debug_level, debug_to_file, debug_timestamps,
+     * debug_microseconds and NULL
+     */
     argv  = talloc_array(mem_ctx, char *, argc);
     if (argv == NULL) {
         DEBUG(1, ("talloc_array failed.\n"));
@@ -422,6 +428,13 @@ static errno_t prepare_child_argv(TALLOC_CTX *mem_ctx,
         goto fail;
     }
 
+    argv[--argc] = talloc_asprintf(argv, "--debug-microseconds=%d",
+                                       child_debug_microseconds);
+    if (argv[argc] == NULL) {
+        ret = ENOMEM;
+        goto fail;
+    }
+
     argv[--argc] = talloc_strdup(argv, binary);
     if (argv[argc] == NULL) {
         ret = ENOMEM;
diff --git a/src/providers/krb5/krb5_child.c b/src/providers/krb5/krb5_child.c
index fc678efa..7f6f9367 100644
--- a/src/providers/krb5/krb5_child.c
+++ b/src/providers/krb5/krb5_child.c
@@ -1554,6 +1554,8 @@ int main(int argc, const char *argv[])
          _("Debug level"), NULL},
         {"debug-timestamps", 0, POPT_ARG_INT, &debug_timestamps, 0,
          _("Add debug timestamps"), NULL},
+        {"debug-microseconds", 0, POPT_ARG_INT, &debug_microseconds, 0,
+         _("Show timestamps with microseconds"), NULL},
         {"debug-fd", 0, POPT_ARG_INT, &debug_fd, 0,
          _("An open file descriptor for the debug logs"), NULL},
         POPT_TABLEEND
diff --git a/src/providers/ldap/ldap_child.c b/src/providers/ldap/ldap_child.c
index 368c2012..b0051fa9 100644
--- a/src/providers/ldap/ldap_child.c
+++ b/src/providers/ldap/ldap_child.c
@@ -360,6 +360,8 @@ int main(int argc, const char *argv[])
          _("Debug level"), NULL},
         {"debug-timestamps", 0, POPT_ARG_INT, &debug_timestamps, 0,
          _("Add debug timestamps"), NULL},
+        {"debug-microseconds", 0, POPT_ARG_INT, &debug_microseconds, 0,
+         _("Show timestamps with microseconds"), NULL},
         {"debug-fd", 0, POPT_ARG_INT, &debug_fd, 0,
          _("An open file descriptor for the debug logs"), NULL},
         POPT_TABLEEND
diff --git a/src/providers/proxy/proxy_auth.c b/src/providers/proxy/proxy_auth.c
index 81ae896b..cd291782 100644
--- a/src/providers/proxy/proxy_auth.c
+++ b/src/providers/proxy/proxy_auth.c
@@ -240,9 +240,10 @@ static struct tevent_req *proxy_child_init_send(TALLOC_CTX *mem_ctx,
     state->child_ctx = child_ctx;
 
     state->command = talloc_asprintf(req,
-            "%s/proxy_child -d %#.4x --debug-timestamps=%d%s --domain %s --id %d",
+            "%s/proxy_child -d %#.4x --debug-timestamps=%d "
+            "--debug-microseconds=%d%s --domain %s --id %d",
             SSSD_LIBEXEC_PATH, debug_level, debug_timestamps,
-            (debug_to_file ? " --debug-to-files" : ""),
+            debug_microseconds, (debug_to_file ? " --debug-to-files" : ""),
             auth_ctx->be->domain->name,
             child_ctx->id);
     if (state->command == NULL) {
diff --git a/src/util/debug.c b/src/util/debug.c
index 3a1b7ca2..7816bc41 100644
--- a/src/util/debug.c
+++ b/src/util/debug.c
@@ -35,6 +35,7 @@ const char *debug_prg_name = "sssd";
 
 int debug_level = SSSDBG_UNRESOLVED;
 int debug_timestamps = SSSDBG_TIMESTAMP_UNRESOLVED;
+int debug_microseconds = SSSDBG_MICROSECONDS_UNRESOLVED;
 int debug_to_file = 0;
 const char *debug_log_file = "sssd";
 FILE *debug_file = NULL;
diff --git a/src/util/server.c b/src/util/server.c
index 42fd9360..0c9501b1 100644
--- a/src/util/server.c
+++ b/src/util/server.c
@@ -382,6 +382,7 @@ int server_setup(const char *name, int flags,
     int ret = EOK;
     bool dt;
     bool dl;
+    bool dm;
     struct tevent_signal *tes;
     struct logrotate_ctx *lctx;
 
@@ -489,6 +490,21 @@ int server_setup(const char *name, int flags,
         else debug_timestamps = 0;
     }
 
+    /* same for debug microseconds */
+    if (debug_microseconds == SSSDBG_MICROSECONDS_UNRESOLVED) {
+        ret = confdb_get_bool(ctx->confdb_ctx, ctx, conf_entry,
+                              CONFDB_SERVICE_DEBUG_MICROSECONDS,
+                              SSSDBG_MICROSECONDS_DEFAULT,
+                              &dm);
+        if (ret != EOK) {
+            DEBUG(0, ("Error reading from confdb (%d) [%s]\n",
+                      ret, strerror(ret)));
+            return ret;
+        }
+        if (dm) debug_microseconds = 1;
+        else debug_microseconds = 0;
+    }
+
     /* same for debug to file */
     dl = (debug_to_file != 0);
     ret = confdb_get_bool(ctx->confdb_ctx, ctx, conf_entry,
diff --git a/src/util/util.h b/src/util/util.h
index c37cab8a..118d70c5 100644
--- a/src/util/util.h
+++ b/src/util/util.h
@@ -54,6 +54,7 @@ typedef int errno_t;
 extern const char *debug_prg_name;
 extern int debug_level;
 extern int debug_timestamps;
+extern int debug_microseconds;
 extern int debug_to_file;
 extern const char *debug_log_file;
 void debug_fn(const char *format, ...);
@@ -80,13 +81,18 @@ errno_t set_debug_file_from_fd(const int fd);
 #define SSSDBG_TIMESTAMP_UNRESOLVED   -1
 #define SSSDBG_TIMESTAMP_DEFAULT       1
 
+#define SSSDBG_MICROSECONDS_UNRESOLVED   -1
+#define SSSDBG_MICROSECONDS_DEFAULT       0
+
 #define SSSD_DEBUG_OPTS \
         {"debug-level", 'd', POPT_ARG_INT, &debug_level, 0, \
          _("Debug level"), NULL}, \
         {"debug-to-files", 'f', POPT_ARG_NONE, &debug_to_file, 0, \
          _("Send the debug output to files instead of stderr"), NULL }, \
         {"debug-timestamps", 0, POPT_ARG_INT, &debug_timestamps, 0, \
-         _("Add debug timestamps"), NULL},
+         _("Add debug timestamps"), NULL}, \
+         {"debug-microseconds", 0, POPT_ARG_INT, &debug_microseconds, 0, \
+          _("Show timestamps with microseconds"), NULL},
 
 /** \def DEBUG(level, body)
     \brief macro to generate debug messages
@@ -107,12 +113,26 @@ errno_t set_debug_file_from_fd(const int fd);
     int __debug_macro_newlevel = debug_get_level(level); \
     if (DEBUG_IS_SET(__debug_macro_newlevel)) { \
         if (debug_timestamps) { \
-            time_t rightnow = time(NULL); \
-            char stamp[25]; \
-            memcpy(stamp, ctime(&rightnow), 24); \
-            stamp[24] = '\0'; \
-            debug_fn("(%s) [%s] [%s] (%#.4x): ", \
-                     stamp, debug_prg_name, __FUNCTION__, __debug_macro_newlevel); \
+            struct timeval __debug_macro_tv; \
+            struct tm *__debug_macro_tm; \
+            char __debug_macro_datetime[20]; \
+            int __debug_macro_year; \
+            gettimeofday(&__debug_macro_tv, NULL); \
+            __debug_macro_tm = localtime(&__debug_macro_tv.tv_sec); \
+            __debug_macro_year = __debug_macro_tm->tm_year + 1900; \
+            /* get date time without year */ \
+            memcpy(__debug_macro_datetime, ctime(&__debug_macro_tv.tv_sec), 19); \
+            __debug_macro_datetime[19] = '\0'; \
+            if (debug_microseconds) { \
+                debug_fn("(%s:%.6d %d) [%s] [%s] (%#.4x): ", \
+                         __debug_macro_datetime, __debug_macro_tv.tv_usec, \
+                         __debug_macro_year, debug_prg_name, \
+                         __FUNCTION__, __debug_macro_newlevel); \
+            } else { \
+                debug_fn("(%s %d) [%s] [%s] (%#.4x): ", \
+                         __debug_macro_datetime, __debug_macro_year, \
+                         debug_prg_name, __FUNCTION__, __debug_macro_newlevel); \
+            } \
         } else { \
             debug_fn("[%s] [%s] (%#.4x): ", \
                      debug_prg_name, __FUNCTION__, __debug_macro_newlevel); \
@@ -134,12 +154,27 @@ errno_t set_debug_file_from_fd(const int fd);
     int __debug_macro_newlevel = debug_get_level(level); \
     if (DEBUG_IS_SET(__debug_macro_newlevel)) { \
         if (debug_timestamps) { \
-            time_t rightnow = time(NULL); \
-            char stamp[25]; \
-            memcpy(stamp, ctime(&rightnow), 24); \
-            stamp[24] = '\0'; \
-            debug_fn("(%s) [%s] [%s] (%#.4x): %s\n", \
-                     stamp, debug_prg_name, function, __debug_macro_newlevel, message); \
+            struct timeval __debug_macro_tv; \
+            struct tm *__debug_macro_tm; \
+            char __debug_macro_datetime[20]; \
+            int __debug_macro_year; \
+            gettimeofday(&__debug_macro_tv, NULL); \
+            __debug_macro_tm = localtime(&__debug_macro_tv.tv_sec); \
+            __debug_macro_year = __debug_macro_tm->tm_year + 1900; \
+            /* get date time without year */ \
+            memcpy(__debug_macro_datetime, ctime(&__debug_macro_tv.tv_sec), 19); \
+            __debug_macro_datetime[19] = '\0'; \
+            if (debug_microseconds) { \
+                debug_fn("(%s:%.6d %d) [%s] [%s] (%#.4x): %s\n", \
+                         __debug_macro_datetime, __debug_macro_tv.tv_usec, \
+                         __debug_macro_year, debug_prg_name, \
+                         function, __debug_macro_newlevel, message); \
+            } else { \
+                debug_fn("(%s %d) [%s] [%s] (%#.4x): %s\n", \
+                         __debug_macro_datetime, __debug_macro_year, \
+                         debug_prg_name, function, __debug_macro_newlevel, \
+                         message); \
+            } \
         } else { \
             debug_fn("[%s] [%s] (%#.4x): %s\n", \
                      debug_prg_name, function, __debug_macro_newlevel, message); \