Add a wait to redirect Krb5 tracing to our stderr

simo5 · simo5 · commit 88bfaa1b67de · 2022-05-27T14:19:03.000-04:00
The proccess stderr may be redirected to a socket or a pipe by the
parent process (which is what systemd does for example).

When that happen we can't simply pass a valid path to stderr so
that libkrb5 can send the tracing via the KRB5_TRACE environment
variable to a our stderr, passing /dev/stderr in this case will
just result in an open error and tracing output going nowhere.

To handle this we create our own fifo to pass to libkrb5 and
then we create a thread that reads the incoming data and pipes
it back to the stderr we've been given by our parent.

Signed-off-by: Simo Sorce &lt;simo@redhat.com&gt;
diff --git a/src/gp_debug.c b/src/gp_debug.c
@@ -3,22 +3,53 @@
 #include "config.h"
 #include <stdbool.h>
 #include <stdlib.h>
+#include "gp_proxy.h"
 #include "gp_debug.h"
 #include "gp_log.h"
 
 /* global debug switch */
 int gp_debug = 0;
 
-void gp_debug_toggle(int level)
+
+void (*gp_debug_setup_k5_trace_fn)(int) = NULL;
+
+void gp_debug_set_krb5_tracing_fn(void (*fn)(int))
 {
-    if (level <= gp_debug)
-        return;
+    if (gp_debug_setup_k5_trace_fn != NULL) {
+        /* deactivate potential previously set tracing
+         * facility */
+        gp_debug_setup_k5_trace_fn(0);
+    }
+
+    gp_debug_setup_k5_trace_fn = fn;
 
-    if (level >= 3 && !getenv("KRB5_TRACE"))
-        setenv("KRB5_TRACE", "/dev/stderr", 1);
+    /* the tracing setup function may be set after the
+     * initial debug level is set via configuration.
+     * Make sure to immedaiately call it if debug level is
+     * already above 3 */
+    if (gp_debug >= 3 && !getenv("KRB5_TRACE")) {
+        gp_debug_setup_k5_trace_fn(1);
+    }
+}
+
+void gp_debug_toggle(int level)
+{
+    if (level >= 3 && !getenv("KRB5_TRACE")) {
+        if (gp_debug_setup_k5_trace_fn) {
+            gp_debug_setup_k5_trace_fn(1);
+        } else {
+            setenv("KRB5_TRACE", "/dev/stderr", 1);
+        }
+    } else if (level < 3) {
+        if (gp_debug_setup_k5_trace_fn) {
+            gp_debug_setup_k5_trace_fn(0);
+        } else {
+            unsetenv("KRB5_TRACE");
+        }
+    }
 
     gp_debug = level;
-    GPDEBUG("Debug Enabled (level: %d)\n", level);
+    GPDEBUG("Debug Level changed to %d\n", gp_debug);
 }
 
 void gp_log_failure(gss_OID mech, uint32_t maj, uint32_t min)
diff --git a/src/gp_debug.h b/src/gp_debug.h
@@ -16,6 +16,7 @@ void gp_debug_toggle(int);
 void gp_debug_printf(const char *format, ...);
 void gp_debug_time_printf(const char *format, ...);
 void gp_debug_set_conn_id(int id);
+void gp_debug_set_krb5_tracing_fn(void (*fn)(int));
 
 #define GPDEBUG(...) do { \
     if (gp_debug) { \
diff --git a/src/gp_init.c b/src/gp_init.c
@@ -110,6 +110,7 @@ void init_done(int wait_fd)
 
 void fini_server(void)
 {
+    gp_krb5_fini_tracing();
     closelog();
 }
 
diff --git a/src/gp_mgmt.c b/src/gp_mgmt.c
@@ -1,8 +1,18 @@
 /* Copyright (C) 2022 the GSS-PROXY contributors, see COPYING for license */
 
+#define _GNU_SOURCE
 #include "config.h"
-#include "gp_proxy.h"
+#include <errno.h>
+#include <fcntl.h>
+#include <pthread.h>
+#include <stdio.h>
+#include <string.h>
+#include <sys/epoll.h>
+#include <sys/stat.h>
+#include <sys/types.h>
 #include <time.h>
+#include <unistd.h>
+#include "gp_proxy.h"
 
 static void idle_terminate(verto_ctx *vctx, verto_ev *ev)
 {
@@ -67,3 +77,213 @@ void gp_activity_accounting(struct gssproxy_ctx *gpctx,
         gpctx->last_activity = now;
     }
 }
+
+#define MAX_K5_EVENTS 10
+static struct k5tracer {
+    pthread_t tid;
+    int fd;
+} *k5tracer = NULL;
+
+static void *k5tracer_thread(void *pvt UNUSED)
+{
+    struct epoll_event ev, events[MAX_K5_EVENTS];
+    int num, epollfd;
+
+    pthread_setcancelstate(PTHREAD_CANCEL_ENABLE, NULL);
+    pthread_setcanceltype(PTHREAD_CANCEL_DEFERRED, NULL);
+
+    fprintf(stderr, "k5tracer_thread started!\n");
+    fflush(stderr);
+
+    epollfd = epoll_create1(EPOLL_CLOEXEC);
+    if (epollfd == -1) {
+        fprintf(stderr, "k5tracer_thread, epoll_create1 failed\n");
+        fflush(stderr);
+        pthread_exit(NULL);
+    }
+
+    ev.events = EPOLLIN;
+    ev.data.fd = k5tracer->fd;
+    if (epoll_ctl(epollfd, EPOLL_CTL_ADD, k5tracer->fd, &ev) == -1) {
+        fprintf(stderr, "k5tracer_thread, epoll_ctl failed\n");
+        fflush(stderr);
+        pthread_exit(NULL);
+    }
+
+
+    for (;;) {
+        num = epoll_wait(epollfd, events, MAX_K5_EVENTS, -1);
+        if (num == -1) {
+            fprintf(stderr, "k5tracer_thread, epoll_wait failed (%d)\n",
+                            errno);
+            fflush(stderr);
+            pthread_exit(NULL);
+        }
+
+        for (int i = 0; i < num; i++) {
+            if (events[i].events & EPOLLIN) {
+                char buf[512];
+                size_t pos = 0;
+                ssize_t rn;
+                size_t wn;
+
+                for (;;) {
+                    rn = read(events[i].data.fd, buf, 512);
+                    if (rn == -1) {
+                        if (errno != EAGAIN && errno != EINTR ) {
+                            fprintf(stderr, "k5tracer_thread, "
+                                            "fatal error on fd %d %d\n",
+                                            events[i].data.fd, errno);
+                            break;
+                        }
+                        rn = 0;
+                    }
+                    if (rn == 0) {
+                        /* done, getting input */
+                        break;
+                    }
+                    /* let's hope all gets written, but if not we just
+                     * missed some debugging output and thatis ok, in
+                     * the very unlikely case it happens */
+                    while (rn > 0) {
+                        wn = fwrite(buf + pos, 1, rn, stderr);
+                        if (wn == 0) break;
+                        rn -= wn;
+                        pos += rn;
+                    }
+                }
+            }
+        }
+        fflush(stderr);
+    }
+}
+
+void free_k5tracer(void)
+{
+    if (k5tracer == NULL) return;
+
+    if (k5tracer->fd > 0) {
+        close(k5tracer->fd);
+    }
+    safefree(k5tracer);
+}
+
+char *tracing_file_name = NULL;
+
+/* if action == 1 activate KRB5 tracing bridge.
+ * if action == 0 deactivate it */
+void gp_krb5_tracing_setup(int action)
+{
+    pthread_attr_t attr;
+    int ret;
+
+    if (action != 0 && action != 1) {
+        GPDEBUGN(3, "%s: Unknown action %d\n", __func__, action);
+        return;
+    }
+
+    if (action == 0) {
+        if (k5tracer) {
+            pthread_cancel(k5tracer->tid);
+            pthread_join(k5tracer->tid, NULL);
+            unsetenv("KRB5_TRACE");
+        }
+        return;
+    }
+
+    /* activate only once */
+    if (k5tracer != NULL) return;
+
+    k5tracer = calloc(1, sizeof(struct k5tracer));
+    if (k5tracer == NULL) {
+        ret = ENOMEM;
+        goto done;
+    }
+
+    /* this name is predictable, but we always unlink it before
+     * creating a new one with permission only for the current
+     * user. A race between unilnk and mkfifo will cause failure
+     * and we'll never open the file that raced us */
+    if (tracing_file_name == NULL) {
+        ret = asprintf(&tracing_file_name,
+                       "/tmp/krb5.tracing.%ld", (long)getpid());
+        if (ret == -1) {
+            ret = errno;
+            goto done;
+        }
+    }
+
+    ret = unlink(tracing_file_name);
+    if (ret == -1 && errno != ENOENT) {
+        ret = errno;
+        GPDEBUGN(3, "%s: unlink(%s) failed\n", __func__, tracing_file_name);
+        goto done;
+    }
+
+    ret = mkfifo(tracing_file_name, 0600);
+    if (ret == -1) {
+        ret = errno;
+        GPDEBUGN(3, "%s: mkfifo(%s) failed\n", __func__, tracing_file_name);
+        goto done;
+    }
+
+    k5tracer->fd = open(tracing_file_name, O_RDONLY | O_CLOEXEC | O_NONBLOCK);
+    if (k5tracer->fd == -1) {
+        ret = errno;
+        GPDEBUGN(3, "%s: open(%s) failed\n", __func__, tracing_file_name);
+        goto done;
+    } else if (k5tracer->fd <= 2) {
+        /* we do not expect stdio to be closed because we need to use it
+         * to forward the tracing, if the fd return is smaller than stderr
+         * consider stdio messed up and just ignore tracing */
+        ret = EINVAL;
+        GPDEBUGN(3, "%s: open(%s) returned fd too low: %d",
+                    __func__, tracing_file_name, k5tracer->fd);
+        close(k5tracer->fd);
+        k5tracer->fd = 0;
+        goto done;
+    }
+
+    ret = pthread_attr_init(&attr);
+    if (ret) {
+        GPDEBUGN(3, "%s: pthread_attr_init failed: %d", __func__, ret);
+        goto done;
+    }
+
+    ret = pthread_attr_setdetachstate(&attr, PTHREAD_CREATE_JOINABLE);
+    if (ret) {
+        GPDEBUGN(3, "%s: pthread_attr_setdetachstate: %d", __func__, ret);
+    }
+
+    ret = pthread_create(&k5tracer->tid, &attr, k5tracer_thread, NULL);
+    if (ret) {
+        pthread_attr_destroy(&attr);
+
+        GPDEBUGN(3, "%s: pthread_create failed: %d", __func__, ret);
+        goto done;
+    }
+
+    pthread_attr_destroy(&attr);
+    setenv("KRB5_TRACE", tracing_file_name, 1);
+
+    ret = 0;
+
+done:
+    if (ret) {
+        char errstr[128]; /* reasonable error str length */
+        GPDEBUGN(3, "%s: Failed to set up krb5 tracing thread: [%s](%d)\n",
+                    __func__, strerror_r(ret, errstr, 128), ret);
+        free_k5tracer();
+    }
+    return;
+}
+
+void gp_krb5_fini_tracing(void)
+{
+    if (tracing_file_name) {
+        /* just in case */
+        gp_krb5_tracing_setup(0);
+        /* remove this one if there */
+        unlink(tracing_file_name);
+    }
+}
diff --git a/src/gp_proxy.h b/src/gp_proxy.h
@@ -133,6 +133,8 @@ int clear_bound_caps(void);
 void idle_handler(struct gssproxy_ctx *gpctx);
 void gp_activity_accounting(struct gssproxy_ctx *gpctx,
                             ssize_t rb, ssize_t wb);
+void gp_krb5_tracing_setup(int action);
+void gp_krb5_fini_tracing(void);
 
 /* from gp_socket.c */
 void free_unix_socket(verto_ctx *ctx, verto_ev *ev);
diff --git a/src/gssproxy.c b/src/gssproxy.c
@@ -86,6 +86,9 @@ int main(int argc, const char *argv[])
         goto cleanup;
     }
 
+    /* set tracing function before handling debug level */
+    gp_debug_set_krb5_tracing_fn(&gp_krb5_tracing_setup);
+
     if (opt_debug || opt_debug_level > 0) {
         if (opt_debug_level == 0) opt_debug_level = 1;
         gp_debug_toggle(opt_debug_level);
@@ -197,7 +200,6 @@ int main(int argc, const char *argv[])
 
     fini_server();
 
-
     ret = 0;
 
 cleanup:

Original file line number	Diff line number	Diff line change
`@@ -110,6 +110,7 @@ void init_done(int wait_fd)`
`110`	`110`
`111`	`111`	`void fini_server(void)`
`112`	`112`	`{`
	`113`	`+ gp_krb5_fini_tracing();`
`113`	`114`	`closelog();`
`114`	`115`	`}`
`115`	`116`