gss: merge enhanced Apple mechglue logging
authorLuke Howard <lukeh@padl.com>
Sat, 28 Dec 2019 05:45:47 +0000 (16:45 +1100)
committerLuke Howard <lukeh@padl.com>
Tue, 4 Feb 2020 06:28:35 +0000 (17:28 +1100)
Add _gss_mg_log() and friends for logging from within the mechanism glue and
SPNEGO. These APIs wrap around the libkrb5 logging APIs.

13 files changed:
lib/gssapi/gssapi/gssapi.h
lib/gssapi/gssapi_mech.h
lib/gssapi/libgssapi-exports.def
lib/gssapi/mech/context.c
lib/gssapi/mech/cred.h
lib/gssapi/mech/gss_accept_sec_context.c
lib/gssapi/mech/gss_acquire_cred_from.c
lib/gssapi/mech/gss_cred.c
lib/gssapi/mech/gss_init_sec_context.c
lib/gssapi/mech/gss_mech_switch.c
lib/gssapi/version-script.map
lib/krb5/libkrb5-exports.def.in
lib/krb5/version-script.map

index f6ab24f16a76188ac5ed4434a9bcbc53129d377f..05fd5977b1a5efbbedfe48f69b45ccd098cffbed 100644 (file)
@@ -1205,6 +1205,9 @@ gss_release_cred_by_mech(
     gss_cred_id_t /* cred_handle */,
     gss_const_OID /* mech */);
 
+GSSAPI_LIB_FUNCTION void GSSAPI_LIB_CALL
+gss_set_log_function(void *ctx, void (*func)(void * ctx, int level, const char *fmt, va_list));
+
 GSSAPI_CPP_END
 
 #if defined(__APPLE__) && (defined(__ppc__) || defined(__ppc64__) || defined(__i386__) || defined(__x86_64__))
index 2e76f065c998e0fac0db856cdac77555a0da1ce1..2c31d1acb370601e3c076a68cd82a64c0d3d6141 100644 (file)
@@ -519,6 +519,9 @@ typedef OM_uint32 GSSAPI_CALLCONV _gss_authorize_localname_t (
               gss_const_OID            /* user_name_type */
              );
 
+struct _gss_name;
+struct _gss_cred;
+
 /* mechglue internal */
 struct gss_mech_compat_desc_struct;
 
@@ -623,4 +626,41 @@ struct _gss_oid_name_table {
 extern struct _gss_oid_name_table _gss_ont_mech[];
 extern struct _gss_oid_name_table _gss_ont_ma[];
 
+int
+_gss_mg_log_level(int level);
+
+void
+_gss_mg_log(int level, const char *fmt, ...)
+    HEIMDAL_PRINTF_ATTRIBUTE((printf, 2, 3));
+
+void
+_gss_mg_log_name(int level,
+                struct _gss_name *name,
+                gss_OID mech_type,
+                const char *fmt, ...);
+
+void
+_gss_mg_log_cred(int level,
+                struct _gss_cred *cred,
+                const char *fmt, ...);
+
+
+void
+_gss_load_plugins(void);
+
+gss_iov_buffer_desc *
+_gss_mg_find_buffer(gss_iov_buffer_desc *iov,
+                   int iov_count,
+                   OM_uint32 type);
+
+OM_uint32
+_gss_mg_allocate_buffer(OM_uint32 *minor_status,
+                       gss_iov_buffer_desc *buffer,
+                       size_t size);
+
+OM_uint32
+gss_mg_set_error_string(gss_OID mech,
+                       OM_uint32 maj, OM_uint32 min,
+                       const char *fmt, ...);
+
 #endif /* GSSAPI_MECH_H */
index e52fb090b550bb52af12eb265b84782c1b7aca1f..6d0f8bb4a3ceb8056575f3474fd11ff4dc9ef1b1 100644 (file)
@@ -90,6 +90,7 @@ EXPORTS
        gss_seal
        gss_set_cred_option
        gss_set_name_attribute
+       gss_set_log_function
        gss_set_neg_mechs
        gss_set_sec_context_option
        gss_sign
index f03534b8631163692ce9557c6b92841983bfd7ae..889ed6160c084694fe6c8dfa957b19eb56453194 100644 (file)
@@ -42,6 +42,7 @@ struct mg_thread_ctx {
     gss_OID mech;
     OM_uint32 min_stat;
     gss_buffer_desc min_error;
+    krb5_context context;
 };
 
 static HEIMDAL_MUTEX context_mutex = HEIMDAL_MUTEX_INITIALIZER;
@@ -60,6 +61,9 @@ destroy_context(void *ptr)
 
     gss_release_buffer(&junk, &mg->min_error);
 
+    if (mg->context)
+       krb5_free_context(mg->context);
+
     free(mg);
 }
 
@@ -88,8 +92,16 @@ _gss_mechglue_thread(void)
        ctx = calloc(1, sizeof(*ctx));
        if (ctx == NULL)
            return NULL;
+
+       ret = krb5_init_context(&ctx->context);
+       if (ret) {
+           free(ctx);
+           return NULL;
+       }
+
        HEIMDAL_setspecific(context_key, ctx, ret);
        if (ret) {
+           krb5_free_context(ctx->context);
            free(ctx);
            return NULL;
        }
@@ -151,8 +163,13 @@ _gss_mg_error(struct gssapi_mech_interface_desc *m, OM_uint32 min)
                                        &m->gm_mech_oid,
                                        &message_content,
                                        &mg->min_error);
-    if (major_status != GSS_S_COMPLETE)
+    if (major_status != GSS_S_COMPLETE) {
        _mg_buffer_zero(&mg->min_error);
+    } else {
+       _gss_mg_log(5, "_gss_mg_error: captured %.*s (%d) from underlying mech %s",
+                   (int)mg->min_error.length, (const char *)mg->min_error.value,
+                   (int)min, m->gm_name);
+    }
 }
 
 void
@@ -163,3 +180,165 @@ gss_mg_collect_error(gss_OID mech, OM_uint32 maj, OM_uint32 min)
        return;
     _gss_mg_error(m, min);
 }
+
+OM_uint32
+gss_mg_set_error_string(gss_OID mech,
+                       OM_uint32 maj, OM_uint32 min,
+                       const char *fmt, ...)
+{
+    struct mg_thread_ctx *mg;
+    char *str = NULL;
+    OM_uint32 junk;
+    va_list ap;
+
+    mg = _gss_mechglue_thread();
+    if (mg == NULL)
+       return maj;
+
+    va_start(ap, fmt);
+    (void) vasprintf(&str, fmt, ap);
+    va_end(ap);
+
+    if (str) {
+       gss_release_buffer(&junk, &mg->min_error);
+
+       mg->mech = mech;
+       mg->min_stat = min;
+
+       mg->min_error.value = str;
+       mg->min_error.length = strlen(str);
+
+       _gss_mg_log(5, "gss_mg_set_error_string: %.*s (%d/%d)",
+                   (int)mg->min_error.length, (const char *)mg->min_error.value,
+                   (int)maj, (int)min);
+    }
+    return maj;
+}
+
+static void *log_ctx = NULL;
+static void (*log_func)(void *ctx, int level, const char *fmt, va_list) = NULL;
+
+void
+gss_set_log_function(void *ctx, void (*func)(void * ctx, int level, const char *fmt, va_list))
+{
+    if (log_func == NULL) {
+       log_func = func;
+       log_ctx = ctx;
+    }
+}
+
+int
+_gss_mg_log_level(int level)
+{
+    struct mg_thread_ctx *mg;
+
+    mg = _gss_mechglue_thread();
+    if (mg == NULL)
+       return 0;
+
+    return _krb5_have_debug(mg->context, level);
+}
+
+/*
+ * TODO: refactor logging so that it no longer depends on libkrb5
+ * and can be configured independently.
+ */
+void
+_gss_mg_log(int level, const char *fmt, ...)
+{
+    struct mg_thread_ctx *mg;
+    va_list ap;
+
+    if (!_gss_mg_log_level(level))
+       return;
+
+    mg = _gss_mechglue_thread();
+    if (mg == NULL)
+       return;
+
+    if (mg->context && _krb5_have_debug(mg->context, level)) {
+       va_start(ap, fmt);
+       krb5_vlog(mg->context, mg->context->debug_dest, level, fmt, ap);
+       va_end(ap);
+    }
+
+    if (log_func) {
+       va_start(ap, fmt);
+       log_func(log_ctx, level, fmt, ap);
+       va_end(ap);
+    }
+}
+
+void
+_gss_mg_log_name(int level,
+                struct _gss_name *name,
+                gss_OID mech_type,
+                const char *fmt, ...)
+{
+    struct _gss_mechanism_name *mn = NULL;
+    gssapi_mech_interface m;
+    OM_uint32 junk;
+
+    if (!_gss_mg_log_level(level))
+        return;
+
+    m = __gss_get_mechanism(mech_type);
+    if (m == NULL)
+        return;
+
+    if (_gss_find_mn(&junk, name, mech_type, &mn) == GSS_S_COMPLETE) {
+       OM_uint32 maj_stat = GSS_S_COMPLETE;
+       gss_buffer_desc namebuf;
+
+       if (mn == NULL) {
+           namebuf.value = "no name";
+           namebuf.length = strlen((char *)namebuf.value);
+       } else {
+           maj_stat = m->gm_display_name(&junk, mn->gmn_name,
+                                         &namebuf, NULL);
+       }
+       if (maj_stat == GSS_S_COMPLETE) {
+           char *str = NULL;
+           va_list ap;
+
+           va_start(ap, fmt);
+           (void) vasprintf(&str, fmt, ap);
+           va_end(ap);
+
+           if (str)
+               _gss_mg_log(level, "%s %.*s", str,
+                           (int)namebuf.length, (char *)namebuf.value);
+           free(str);
+           if (mn != NULL)
+               gss_release_buffer(&junk, &namebuf);
+       }
+    }
+
+}
+
+void
+_gss_mg_log_cred(int level,
+                struct _gss_cred *cred,
+                const char *fmt, ...)
+{
+    struct _gss_mechanism_cred *mc;
+    char *str;
+    va_list ap;
+
+    if (!_gss_mg_log_level(level))
+        return;
+
+    va_start(ap, fmt);
+    (void) vasprintf(&str, fmt, ap);
+    va_end(ap);
+
+    if (cred) {
+       HEIM_TAILQ_FOREACH(mc, &cred->gc_mc, gmc_link) {
+           _gss_mg_log(1, "%s: %s", str, mc->gmc_mech->gm_name);
+       }
+    } else {
+       _gss_mg_log(1, "%s: GSS_C_NO_CREDENTIAL", str);
+    }
+    free(str);
+}
+
index 7ae22fc4ab5a8601abfaff568a5badeb7126ffbc..d45067110e69c4551f0a4f74dab2e24c3694fc49 100644 (file)
@@ -48,9 +48,6 @@ _gss_mg_release_cred(struct _gss_cred *cred);
 struct _gss_mechanism_cred *
 _gss_copy_cred(struct _gss_mechanism_cred *mc);
 
-void
-_gss_mg_check_credential(gss_const_cred_id_t credential);
-
 struct _gss_mechanism_name;
 
 OM_uint32
index 100ac74273cef5cbf15bd74ccaf9e088743a327c..2b6a1c5a16e82182c18571cada7a4bb0a93c7abf 100644 (file)
@@ -136,6 +136,8 @@ choose_mech(const gss_buffer_t input, gss_OID *mech_oid)
                return GSS_S_COMPLETE;
        }
 
+       _gss_mg_log(10, "Don't have client request mech");
+
        return status;
 }
 
@@ -176,7 +178,6 @@ gss_accept_sec_context(OM_uint32 *minor_status,
            *delegated_cred_handle = GSS_C_NO_CREDENTIAL;
        _mg_buffer_zero(output_token);
 
-
        /*
         * If this is the first call (*context_handle is NULL), we must
         * parse the input token to figure out the mechanism to use.
@@ -201,6 +202,7 @@ gss_accept_sec_context(OM_uint32 *minor_status,
                m = ctx->gc_mech = __gss_get_mechanism(mech_oid);
                if (!m) {
                        free(ctx);
+                       _gss_mg_log(10, "mechanism client used is unknown");
                        return (GSS_S_BAD_MECH);
                }
                *context_handle = (gss_ctx_id_t) ctx;
@@ -214,6 +216,11 @@ gss_accept_sec_context(OM_uint32 *minor_status,
                                break;
                if (!mc) {
                        gss_delete_sec_context(&junk, context_handle, NULL);
+                       _gss_mg_log(10, "gss-asc: client sent mech %s "
+                                   "but no credential was matching",
+                                   m->gm_name);
+                       HEIM_TAILQ_FOREACH(mc, &cred->gc_mc, gmc_link)
+                               _gss_mg_log(10, "gss-asc: available creds were %s", mc->gmc_mech->gm_name);
                        return (GSS_S_BAD_MECH);
                }
                acceptor_mc = mc->gmc_cred;
@@ -301,6 +308,8 @@ gss_accept_sec_context(OM_uint32 *minor_status,
                }
        }
 
+       _gss_mg_log(10, "gss-asc: return %d/%d", (int)major_status, (int)*minor_status);
+
        if (ret_flags)
            *ret_flags = mech_ret_flags;
        return (major_status);
index 9293da91b4348fce04ea36530f9fad775aee9951..f0ddd6b679fe9ad7d3ced12867f92c6f71227d66 100644 (file)
@@ -219,6 +219,11 @@ gss_acquire_cred_from(OM_uint32 *minor_status,
            continue;
         }
 
+       _gss_mg_log_name(10, name, &mechs->elements[i],
+                        "gss_acquire_cred %s name: %ld/%ld",
+                        m->gm_name,
+                        (long)major_status, (long)*minor_status);
+
        HEIM_TAILQ_INSERT_TAIL(&cred->gc_mc, mc, gmc_link);
 
        if (cred_time < min_time)
@@ -253,6 +258,8 @@ gss_acquire_cred_from(OM_uint32 *minor_status,
     if (time_rec)
         *time_rec = min_time;
 
+    _gss_mg_log_cred(10, cred, "gss_acquire_cred_from");
+
 cleanup:
     if (major_status != GSS_S_COMPLETE) {
        gss_release_cred(&minor, (gss_cred_id_t *)&cred);
index 79f11e090c0b974eefb04aec7844a0d1a515148c..1a7210e73a1bf7fea15648f72ce1abf9d870abe1 100644 (file)
@@ -66,6 +66,9 @@ gss_export_cred(OM_uint32 * minor_status,
     HEIM_TAILQ_FOREACH(mc, &cred->gc_mc, gmc_link) {
        if (mc->gmc_mech->gm_export_cred == NULL) {
            *minor_status = 0;
+           gss_mg_set_error_string(&mc->gmc_mech->gm_mech_oid,
+                                   GSS_S_NO_CRED, *minor_status,
+                                   "Credential doesn't support exporting");
            return GSS_S_NO_CRED;
        }
     }
@@ -77,7 +80,6 @@ gss_export_cred(OM_uint32 * minor_status,
     }
 
     HEIM_TAILQ_FOREACH(mc, &cred->gc_mc, gmc_link) {
-
        major = mc->gmc_mech->gm_export_cred(minor_status,
                                             mc->gmc_cred, &buffer);
        if (major) {
@@ -85,12 +87,14 @@ gss_export_cred(OM_uint32 * minor_status,
            return major;
        }
 
-       bytes = krb5_storage_write(sp, buffer.value, buffer.length);
-       if (bytes < 0 || (size_t)bytes != buffer.length) {
-           gss_release_buffer(minor_status, &buffer);
-           krb5_storage_free(sp);
-           *minor_status = EINVAL;
-           return GSS_S_FAILURE;
+       if (buffer.length) {
+           bytes = krb5_storage_write(sp, buffer.value, buffer.length);
+           if (bytes < 0 || (size_t)bytes != buffer.length) {
+               gss_release_buffer(minor_status, &buffer);
+               krb5_storage_free(sp);
+               *minor_status = EINVAL;
+               return GSS_S_FAILURE;
+           }
        }
        gss_release_buffer(minor_status, &buffer);
     }
@@ -102,6 +106,14 @@ gss_export_cred(OM_uint32 * minor_status,
        return GSS_S_FAILURE;
     }
 
+    if (data.length == 0) {
+       *minor_status = 0;
+       gss_mg_set_error_string(GSS_C_NO_OID,
+                               GSS_S_NO_CRED, *minor_status,
+                               "Credential was not exportable");
+       return GSS_S_NO_CRED;
+    }
+
     token->value = data.data;
     token->length = data.length;
 
index 5f17694401095b31f9a705dc759904b3f5e615ae..5d9180abb7cc4b95e85957c0f5d21ab2681ef521 100644 (file)
@@ -46,6 +46,38 @@ _gss_mech_cred_find(gss_const_cred_id_t cred_handle, gss_OID mech_type)
        return GSS_C_NO_CREDENTIAL;
 }
 
+static void
+log_init_sec_context(struct _gss_context *ctx,
+                    struct _gss_name *target,
+                    OM_uint32 req_flags,
+                    struct _gss_cred *cred,
+                    gss_OID mech_type,
+                    gss_buffer_t input_token)
+{
+    gssapi_mech_interface m;
+
+    if (ctx)
+       m = ctx->gc_mech;
+    else
+       m = __gss_get_mechanism(mech_type);
+    if (m == NULL)
+       return;
+
+    mech_type = &m->gm_mech_oid;
+
+    _gss_mg_log(1, "gss_isc: %s %sfirst flags %08x, %s cred, %stoken",
+               m->gm_name,
+               (ctx == NULL) ? "" : "not ",
+               req_flags,
+               (cred != NULL) ? "specific" : "default",
+               (input_token != NULL && input_token->length) ? "" : "no ");
+
+    _gss_mg_log_cred(1, cred, "gss_isc cred");
+
+    /* print target name */
+    _gss_mg_log_name(1, target, mech_type, "gss_isc: target");
+}
+
 /**
  * As the initiator build a context with an acceptor.
  *
@@ -141,6 +173,11 @@ gss_init_sec_context(OM_uint32 * minor_status,
        if (time_rec)
            *time_rec = 0;
 
+       if (_gss_mg_log_level(1))
+           log_init_sec_context(ctx, name, req_flags,
+                                (struct _gss_cred *)initiator_cred_handle,
+                                input_mech_type, input_token);
+
        /*
         * If we haven't allocated a context yet, do so now and lookup
         * the mechanism switch table. If we have one already, make
@@ -159,6 +196,10 @@ gss_init_sec_context(OM_uint32 * minor_status,
                m = ctx->gc_mech = __gss_get_mechanism(mech_type);
                if (!m) {
                        free(ctx);
+                       *minor_status = 0;
+                       gss_mg_set_error_string(mech_type, GSS_S_BAD_MECH,
+                                               *minor_status,
+                                               "Unsupported mechanism requested");
                        return (GSS_S_BAD_MECH);
                }
                allocated_ctx = 1;
@@ -188,9 +229,14 @@ gss_init_sec_context(OM_uint32 * minor_status,
 
         if (initiator_cred_handle != GSS_C_NO_CREDENTIAL &&
             cred_handle == NULL) {
+           *minor_status = 0;
             if (allocated_ctx)
                 free(ctx);
-            return GSS_S_NO_CRED;
+           gss_mg_set_error_string(mech_type, GSS_S_UNAVAILABLE,
+                                   *minor_status,
+                                   "Credential for the requested mechanism "
+                                   "not found in credential handle");
+            return GSS_S_UNAVAILABLE;
         }
 
        major_status = m->gm_init_sec_context(minor_status,
@@ -217,5 +263,8 @@ gss_init_sec_context(OM_uint32 * minor_status,
                *context_handle = (gss_ctx_id_t) ctx;
        }
 
+       _gss_mg_log(1, "gss_isc: %s maj_stat: %d/%d",
+                   m->gm_name, (int)major_status, (int)*minor_status);
+
        return (major_status);
 }
index c9ccb2c77284c9b9e1a9ddcbd05ab7ab2934fbbd..6bad68611becd745a7ca67d1cdb97809ff495a1c 100644 (file)
@@ -167,7 +167,7 @@ do {                                                                        \
        m->gm_mech.gm_ ## name = (_gss_##name##_t *)dlsym(so, "gss_" #name); \
        if (!m->gm_mech.gm_ ## name ||                                  \
            m->gm_mech.gm_ ##name == gss_ ## name) {                    \
-               fprintf(stderr, "can't find symbol gss_" #name "\n");   \
+               _gss_mg_log(1, "can't find symbol gss_" #name "\n");    \
                goto bad;                                               \
        }                                                               \
 } while (0)
@@ -326,7 +326,7 @@ _gss_load_mech(void)
 
                so = dlopen(lib, RTLD_LAZY | RTLD_LOCAL | RTLD_GROUP);
                if (so == NULL) {
-/*                     fprintf(stderr, "dlopen: %s\n", dlerror()); */
+                       _gss_mg_log(1, "dlopen: %s\n", dlerror());
                        goto bad;
                }
 
index 3265970344f551542ecd8f2e8db4c4c339683b19..ddc42e8ea2b01d5ceff8123b5a9e48cda15f2ee6 100644 (file)
@@ -84,6 +84,7 @@ HEIMDAL_GSS_2.0 {
                gss_seal;
                gss_set_cred_option;
                gss_set_name_attribute;
+               gss_set_log_function;
                gss_set_neg_mechs;
                gss_set_sec_context_option;
                gss_sign;
index 42fb40b209e3ea23d6afafd2d263d8cea7e69396..561ca7ef82d3c494dbab062cb8853a08d0c166e9 100644 (file)
@@ -776,6 +776,7 @@ EXPORTS
        _krb5_get_krbtgt
        _krb5_build_authenticator
        _krb5_kt_client_default_name
+       _krb5_have_debug
 
        ; Shared with libkadm5
        _krb5_load_plugins
index e4a765804b86d9b9592d20171b391342d77850a2..d35fb3c0469235a662036c7f2c261e9e875e4c77 100644 (file)
@@ -768,6 +768,7 @@ HEIMDAL_KRB5_2.0 {
                _krb5_get_krbtgt;
                _krb5_build_authenticator;
                _krb5_kt_client_default_name;
+               _krb5_have_debug;
 
                # Shared with libkadm5
                _krb5_load_plugins;