Add options to specify a debug level

Print only messages that are at that level or lower.
Also add timestamps to debug messages.

Signed-off-by: Simo Sorce <simo@redhat.com>
Reviewed-by: Robbie Harwood <rharwood@redhat.com>

6 files changed, 72 insertions, 13 deletions

diff --git a/proxy/src/gp_config.c b/proxy/src/gp_config.c
index 64c790f..6398f28 100644
--- a/proxy/src/gp_config.c
+++ b/proxy/src/gp_config.c
@@ -478,6 +478,7 @@ int load_config(struct gp_config *cfg)
 {
     struct gp_ini_context *ctx;
     const char *tmpstr;
+    int tmpint = 0;
     int ret;
 
     ret = gp_init_ini_context(cfg->config_file, cfg->config_dir, &ctx);
@@ -488,12 +489,19 @@ int load_config(struct gp_config *cfg)
     ret = gp_config_get_string(ctx, "gssproxy", "debug", &tmpstr);
     if (ret == 0) {
         if (gp_boolean_is_true(tmpstr)) {
-            gp_debug_enable();
+            gp_debug_enable(1);
         }
     } else if (ret != ENOENT) {
         goto done;
     }
 
+    ret = gp_config_get_int(ctx, "gssproxy", "debug_level", &tmpint);
+    if (ret == 0) {
+        gp_debug_enable(tmpint);
+    } else if (ret != ENOENT) {
+        goto done;
+    }
+
     ret = gp_config_get_string(ctx, "gssproxy", "run_as_user", &tmpstr);
     if (ret == 0) {
         cfg->proxy_user = strdup(tmpstr);
diff --git a/proxy/src/gp_debug.c b/proxy/src/gp_debug.c
index f047e0d..4a1a26c 100644
--- a/proxy/src/gp_debug.c
+++ b/proxy/src/gp_debug.c
@@ -7,10 +7,11 @@
 /* global debug switch */
 int gp_debug;
 
-void gp_debug_enable(void)
+void gp_debug_enable(int level)
 {
-    gp_debug = 1;
-    GPDEBUG("Debug Enabled\n");
+    if (level == 0) level = 1;
+    gp_debug = level;
+    GPDEBUG("Debug Enabled (level: %d)\n", level);
 }
 
 void gp_log_failure(gss_OID mech, uint32_t maj, uint32_t min)
@@ -21,3 +22,38 @@ void gp_log_failure(gss_OID mech, uint32_t maj, uint32_t min)
 
     fprintf(stderr, "Failed with: %s\n", buf);
 }
+
+const char *gp_debug_timestamp(void)
+{
+    static __thread char buffer[24];
+    static __thread time_t timestamp = 0;
+    struct tm tm_info;
+    time_t now;
+
+    time(&now);
+    if (now == timestamp) return buffer;
+
+    gmtime_r(&now, &tm_info);
+    strftime(buffer, 24, "[%Y/%m/%d %H:%M:%S]: ", &tm_info);
+    timestamp = now;
+    return buffer;
+}
+
+void gp_debug_printf(const char *format, ...)
+{
+    va_list varargs;
+    va_start(varargs, format);
+    vfprintf(stderr, format, varargs);
+    va_end(varargs);
+}
+
+void gp_debug_time_printf(const char *format, ...)
+{
+    va_list varargs;
+
+    fprintf(stderr, "%s", gp_debug_timestamp());
+
+    va_start(varargs, format);
+    vfprintf(stderr, format, varargs);
+    va_end(varargs);
+}
diff --git a/proxy/src/gp_debug.h b/proxy/src/gp_debug.h
index 7b665a1..b4dbf80 100644
--- a/proxy/src/gp_debug.h
+++ b/proxy/src/gp_debug.h
@@ -4,15 +4,25 @@
 #define _GP_DEBUG_H_
 
 #include <gssapi/gssapi.h>
+#include <stdarg.h>
 #include <stdio.h>
+#include <time.h>
 
 extern int gp_debug;
 
-void gp_debug_enable(void);
+void gp_debug_enable(int);
+void gp_debug_printf(const char *format, ...);
+void gp_debug_time_printf(const char *format, ...);
 
 #define GPDEBUG(...) do { \
     if (gp_debug) { \
-        fprintf(stderr, __VA_ARGS__); \
+        gp_debug_time_printf(__VA_ARGS__); \
+    } \
+} while(0)
+
+#define GPDEBUGN(lvl, ...) do { \
+    if (lvl <= gp_debug) { \
+        gp_debug_time_printf(__VA_ARGS__); \
     } \
 } while(0)
 
diff --git a/proxy/src/gp_rpc_process.c b/proxy/src/gp_rpc_process.c
index f4ad2f8..d1a0232 100644
--- a/proxy/src/gp_rpc_process.c
+++ b/proxy/src/gp_rpc_process.c
@@ -313,9 +313,10 @@ static const char *gp_rpc_procname(uint32_t proc)
 static int gp_rpc_execute(struct gp_call_ctx *gpcall, uint32_t proc,
                           union gp_rpc_arg *arg, union gp_rpc_res *res)
 {
-    GPDEBUG("gp_rpc_execute: executing %d (%s) for service \"%s\", euid: %d, socket: %s\n",
-        proc, gp_rpc_procname(proc), gpcall->service->name,
-        gp_conn_get_uid(gpcall->connection), gpcall->service->socket);
+    GPDEBUG("gp_rpc_execute: executing %d (%s) for service \"%s\", euid: %d,"
+            "socket: %s\n", proc, gp_rpc_procname(proc),
+            gpcall->service->name, gp_conn_get_uid(gpcall->connection),
+            gpcall->service->socket);
 
     return gp_xdr_set[proc].exec_fn(gpcall, arg, res);
 }
diff --git a/proxy/src/gssproxy.c b/proxy/src/gssproxy.c
index 1e99f88..bcf236b 100644
--- a/proxy/src/gssproxy.c
+++ b/proxy/src/gssproxy.c
@@ -149,6 +149,7 @@ int main(int argc, const char *argv[])
     int opt_interactive = 0;
     int opt_version = 0;
     int opt_debug = 0;
+    int opt_debug_level = 0;
     verto_ctx *vctx;
     verto_ev *ev;
     int wait_fd;
@@ -168,8 +169,10 @@ int main(int argc, const char *argv[])
          _("Specify a custom default socket"), NULL}, \
         {"debug", 'd', POPT_ARG_NONE, &opt_debug, 0, \
          _("Enable debugging"), NULL}, \
-         {"version", '\0', POPT_ARG_NONE, &opt_version, 0, \
-          _("Print version number and exit"), NULL }, \
+        {"debug-level", '\0', POPT_ARG_INT, &opt_debug_level, 0, \
+         _("Set debugging level"), NULL}, \
+        {"version", '\0', POPT_ARG_NONE, &opt_version, 0, \
+         _("Print version number and exit"), NULL }, \
         POPT_TABLEEND
     };
 
@@ -189,8 +192,8 @@ int main(int argc, const char *argv[])
         return 0;
     }
 
-    if (opt_debug) {
-        gp_debug_enable();
+    if (opt_debug || opt_debug_level > 0) {
+        gp_debug_enable(opt_debug_level);
     }
 
     if (opt_daemon && opt_interactive) {
diff --git a/proxy/tests/runtests.py b/proxy/tests/runtests.py
index fcc364e..0f1b85b 100755
--- a/proxy/tests/runtests.py
+++ b/proxy/tests/runtests.py
@@ -301,6 +301,7 @@ def run_interposetest(testdir, env):
 
 GSSPROXY_CONF_TEMPLATE = '''
 [gssproxy]
+  debug_level = 2
 
 [service/test]
   mechs = krb5