DEBUG timestamps offer higher precision

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

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

3 files changed, 65 insertions, 13 deletions

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); \