gss: merge enhanced Apple mechglue logging

Add _gss_mg_log() and friends for logging from within the mechanism glue and
SPNEGO. These APIs wrap around the libkrb5 logging APIs.

lib/gssapi/gssapi/gssapi.h

@@ -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__))

lib/gssapi/gssapi_mech.h

@@ -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 */

lib/gssapi/libgssapi-exports.def

@@ -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

lib/gssapi/mech/context.c

@@ -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);
+}
+

lib/gssapi/mech/cred.h

@@ -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

lib/gssapi/mech/gss_accept_sec_context.c

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

lib/gssapi/mech/gss_acquire_cred_from.c

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

lib/gssapi/mech/gss_cred.c

@@ -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;
 

lib/gssapi/mech/gss_init_sec_context.c

@@ -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);
 }

lib/gssapi/mech/gss_mech_switch.c

@@ -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;
 		}
 

lib/gssapi/version-script.map

@@ -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;

lib/krb5/libkrb5-exports.def.in

@@ -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

lib/krb5/version-script.map

@@ -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;