Add a "-v" (verbose) option to the gssd daemon, to help

with diagnosis of kerberized NFS mount problems. When set,
messages are sent to syslog() (or fprintf(stderr,...) if
"-d" is also specified) to indicate activity/results of
kgssapi upcalls.

Reviewed by:	jhb
MFC after:	2 weeks

1 files changed, 78 insertions, 2 deletions

diff --git a/usr.sbin/gssd/gssd.c b/usr.sbin/gssd/gssd.c
index a50e097..46f7c6d 100644
--- a/usr.sbin/gssd/gssd.c
+++ b/usr.sbin/gssd/gssd.c
@@ -71,10 +71,12 @@ uint32_t gss_start_time;
 int debug_level;
 static char ccfile_dirlist[PATH_MAX + 1], ccfile_substring[NAME_MAX + 1];
 static char pref_realm[1024];
+static int verbose;
 
 static void gssd_load_mech(void);
 static int find_ccache_file(const char *, uid_t, char *);
 static int is_a_valid_tgt_cache(const char *, uid_t, int *, time_t *);
+static void gssd_verbose_out(const char *, ...);
 
 extern void gssd_1(struct svc_req *rqstp, SVCXPRT *transp);
 extern int gssd_syscall(char *path);
@@ -99,11 +101,15 @@ main(int argc, char **argv)
 	ccfile_dirlist[0] = '\0';
 	pref_realm[0] = '\0';
 	debug = 0;
-	while ((ch = getopt(argc, argv, "ds:c:r:")) != -1) {
+	verbose = 0;
+	while ((ch = getopt(argc, argv, "dvs:c:r:")) != -1) {
 		switch (ch) {
 		case 'd':
 			debug_level++;
 			break;
+		case 'v':
+			verbose = 1;
+			break;
 		case 's':
 #ifndef WITHOUT_KERBEROS
 			/*
@@ -299,10 +305,26 @@ gssd_delete_resource(uint64_t id)
 	}
 }
 
+static void
+gssd_verbose_out(const char *fmt, ...)
+{
+	va_list ap;
+
+	if (verbose != 0) {
+		va_start(ap, fmt);
+		if (debug_level == 0)
+			vsyslog(LOG_INFO | LOG_DAEMON, fmt, ap);
+		else
+			vfprintf(stderr, fmt, ap);
+		va_end(ap);
+	}
+}
+
 bool_t
 gssd_null_1_svc(void *argp, void *result, struct svc_req *rqstp)
 {
 
+	gssd_verbose_out("gssd_null: done\n");
 	return (TRUE);
 }
 
@@ -337,6 +359,9 @@ gssd_init_sec_context_1_svc(init_sec_context_args *argp, init_sec_context_res *r
 		} while (cp != NULL && *cp != '\0');
 		if (gotone == 0) {
 			result->major_status = GSS_S_CREDENTIALS_EXPIRED;
+			gssd_verbose_out("gssd_init_sec_context: -s no"
+			    " credential cache file found for uid=%d\n",
+			    (int)argp->uid);
 			return (TRUE);
 		}
 	} else {
@@ -362,6 +387,8 @@ gssd_init_sec_context_1_svc(init_sec_context_args *argp, init_sec_context_res *r
 		cred = gssd_find_resource(argp->cred);
 		if (!cred) {
 			result->major_status = GSS_S_CREDENTIALS_EXPIRED;
+			gssd_verbose_out("gssd_init_sec_context: cred"
+			    " resource not found\n");
 			return (TRUE);
 		}
 	}
@@ -369,6 +396,8 @@ gssd_init_sec_context_1_svc(init_sec_context_args *argp, init_sec_context_res *r
 		ctx = gssd_find_resource(argp->ctx);
 		if (!ctx) {
 			result->major_status = GSS_S_CONTEXT_EXPIRED;
+			gssd_verbose_out("gssd_init_sec_context: context"
+			    " resource not found\n");
 			return (TRUE);
 		}
 	}
@@ -376,6 +405,8 @@ gssd_init_sec_context_1_svc(init_sec_context_args *argp, init_sec_context_res *r
 		name = gssd_find_resource(argp->name);
 		if (!name) {
 			result->major_status = GSS_S_BAD_NAME;
+			gssd_verbose_out("gssd_init_sec_context: name"
+			    " resource not found\n");
 			return (TRUE);
 		}
 	}
@@ -385,6 +416,9 @@ gssd_init_sec_context_1_svc(init_sec_context_args *argp, init_sec_context_res *r
 	    argp->req_flags, argp->time_req, argp->input_chan_bindings,
 	    &argp->input_token, &result->actual_mech_type,
 	    &result->output_token, &result->ret_flags, &result->time_rec);
+	gssd_verbose_out("gssd_init_sec_context: done major=0x%x minor=%d"
+	    " uid=%d\n", (unsigned int)result->major_status,
+	    (int)result->minor_status, (int)argp->uid);
 
 	if (result->major_status == GSS_S_COMPLETE
 	    || result->major_status == GSS_S_CONTINUE_NEEDED) {
@@ -410,6 +444,8 @@ gssd_accept_sec_context_1_svc(accept_sec_context_args *argp, accept_sec_context_
 		ctx = gssd_find_resource(argp->ctx);
 		if (!ctx) {
 			result->major_status = GSS_S_CONTEXT_EXPIRED;
+			gssd_verbose_out("gssd_accept_sec_context: ctx"
+			    " resource not found\n");
 			return (TRUE);
 		}
 	}
@@ -417,6 +453,8 @@ gssd_accept_sec_context_1_svc(accept_sec_context_args *argp, accept_sec_context_
 		cred = gssd_find_resource(argp->cred);
 		if (!cred) {
 			result->major_status = GSS_S_CREDENTIALS_EXPIRED;
+			gssd_verbose_out("gssd_accept_sec_context: cred"
+			    " resource not found\n");
 			return (TRUE);
 		}
 	}
@@ -427,6 +465,8 @@ gssd_accept_sec_context_1_svc(accept_sec_context_args *argp, accept_sec_context_
 	    &src_name, &result->mech_type, &result->output_token,
 	    &result->ret_flags, &result->time_rec,
 	    &delegated_cred_handle);
+	gssd_verbose_out("gssd_accept_sec_context: done major=0x%x minor=%d\n",
+	    (unsigned int)result->major_status, (int)result->minor_status);
 
 	if (result->major_status == GSS_S_COMPLETE
 	    || result->major_status == GSS_S_CONTINUE_NEEDED) {
@@ -455,6 +495,8 @@ gssd_delete_sec_context_1_svc(delete_sec_context_args *argp, delete_sec_context_
 		result->major_status = GSS_S_COMPLETE;
 		result->minor_status = 0;
 	}
+	gssd_verbose_out("gssd_delete_sec_context: done major=0x%x minor=%d\n",
+	    (unsigned int)result->major_status, (int)result->minor_status);
 
 	return (TRUE);
 }
@@ -476,6 +518,8 @@ gssd_export_sec_context_1_svc(export_sec_context_args *argp, export_sec_context_
 		result->interprocess_token.length = 0;
 		result->interprocess_token.value = NULL;
 	}
+	gssd_verbose_out("gssd_export_sec_context: done major=0x%x minor=%d\n",
+	    (unsigned int)result->major_status, (int)result->minor_status);
 
 	return (TRUE);
 }
@@ -487,6 +531,8 @@ gssd_import_name_1_svc(import_name_args *argp, import_name_res *result, struct s
 
 	result->major_status = gss_import_name(&result->minor_status,
 	    &argp->input_name_buffer, argp->input_name_type, &name);
+	gssd_verbose_out("gssd_import_name: done major=0x%x minor=%d\n",
+	    (unsigned int)result->major_status, (int)result->minor_status);
 
 	if (result->major_status == GSS_S_COMPLETE)
 		result->output_name = gssd_make_resource(name);
@@ -510,6 +556,8 @@ gssd_canonicalize_name_1_svc(canonicalize_name_args *argp, canonicalize_name_res
 
 	result->major_status = gss_canonicalize_name(&result->minor_status,
 	    name, argp->mech_type, &output_name);
+	gssd_verbose_out("gssd_canonicalize_name: done major=0x%x minor=%d\n",
+	    (unsigned int)result->major_status, (int)result->minor_status);
 
 	if (result->major_status == GSS_S_COMPLETE)
 		result->output_name = gssd_make_resource(output_name);
@@ -527,11 +575,14 @@ gssd_export_name_1_svc(export_name_args *argp, export_name_res *result, struct s
 	memset(result, 0, sizeof(*result));
 	if (!name) {
 		result->major_status = GSS_S_BAD_NAME;
+		gssd_verbose_out("gssd_export_name: name resource not found\n");
 		return (TRUE);
 	}
 
 	result->major_status = gss_export_name(&result->minor_status,
 	    name, &result->exported_name);
+	gssd_verbose_out("gssd_export_name: done major=0x%x minor=%d\n",
+	    (unsigned int)result->major_status, (int)result->minor_status);
 
 	return (TRUE);
 }
@@ -549,6 +600,8 @@ gssd_release_name_1_svc(release_name_args *argp, release_name_res *result, struc
 		result->major_status = GSS_S_COMPLETE;
 		result->minor_status = 0;
 	}
+	gssd_verbose_out("gssd_release_name: done major=0x%x minor=%d\n",
+	    (unsigned int)result->major_status, (int)result->minor_status);
 
 	return (TRUE);
 }
@@ -600,17 +653,27 @@ gssd_pname_to_uid_1_svc(pname_to_uid_args *argp, pname_to_uid_res *result, struc
 					mem_alloc(len * sizeof(int));
 				memcpy(result->gidlist.gidlist_val, groups,
 				    len * sizeof(int));
+				gssd_verbose_out("gssd_pname_to_uid: mapped"
+				    " to uid=%d, gid=%d\n", (int)result->uid,
+				    (int)result->gid);
 			} else {
 				result->gid = 65534;
 				result->gidlist.gidlist_len = 0;
 				result->gidlist.gidlist_val = NULL;
+				gssd_verbose_out("gssd_pname_to_uid: mapped"
+				    " to uid=%d, but no groups\n",
+				    (int)result->uid);
 			}
 			if (bufp != NULL && buflen > sizeof(buf))
 				free(bufp);
-		}
+		} else
+			gssd_verbose_out("gssd_pname_to_uid: failed major=0x%x"
+			    " minor=%d\n", (unsigned int)result->major_status,
+			    (int)result->minor_status);
 	} else {
 		result->major_status = GSS_S_BAD_NAME;
 		result->minor_status = 0;
+		gssd_verbose_out("gssd_pname_to_uid: no name\n");
 	}
 
 	return (TRUE);
@@ -646,6 +709,8 @@ gssd_acquire_cred_1_svc(acquire_cred_args *argp, acquire_cred_res *result, struc
 		} while (cp != NULL && *cp != '\0');
 		if (gotone == 0) {
 			result->major_status = GSS_S_CREDENTIALS_EXPIRED;
+			gssd_verbose_out("gssd_acquire_cred: no cred cache"
+			    " file found\n");
 			return (TRUE);
 		}
 	} else {
@@ -672,6 +737,8 @@ gssd_acquire_cred_1_svc(acquire_cred_args *argp, acquire_cred_res *result, struc
 		desired_name = gssd_find_resource(argp->desired_name);
 		if (!desired_name) {
 			result->major_status = GSS_S_BAD_NAME;
+			gssd_verbose_out("gssd_acquire_cred: no desired name"
+			    " found\n");
 			return (TRUE);
 		}
 	}
@@ -679,6 +746,8 @@ gssd_acquire_cred_1_svc(acquire_cred_args *argp, acquire_cred_res *result, struc
 	result->major_status = gss_acquire_cred(&result->minor_status,
 	    desired_name, argp->time_req, argp->desired_mechs,
 	    argp->cred_usage, &cred, &result->actual_mechs, &result->time_rec);
+	gssd_verbose_out("gssd_acquire_cred: done major=0x%x minor=%d\n",
+	    (unsigned int)result->major_status, (int)result->minor_status);
 
 	if (result->major_status == GSS_S_COMPLETE)
 		result->output_cred = gssd_make_resource(cred);
@@ -696,11 +765,14 @@ gssd_set_cred_option_1_svc(set_cred_option_args *argp, set_cred_option_res *resu
 	memset(result, 0, sizeof(*result));
 	if (!cred) {
 		result->major_status = GSS_S_CREDENTIALS_EXPIRED;
+		gssd_verbose_out("gssd_set_cred: no credentials\n");
 		return (TRUE);
 	}
 
 	result->major_status = gss_set_cred_option(&result->minor_status,
 	    &cred, argp->option_name, &argp->option_value);
+	gssd_verbose_out("gssd_set_cred: done major=0x%x minor=%d\n",
+	    (unsigned int)result->major_status, (int)result->minor_status);
 
 	return (TRUE);
 }
@@ -718,6 +790,8 @@ gssd_release_cred_1_svc(release_cred_args *argp, release_cred_res *result, struc
 		result->major_status = GSS_S_COMPLETE;
 		result->minor_status = 0;
 	}
+	gssd_verbose_out("gssd_release_cred: done major=0x%x minor=%d\n",
+	    (unsigned int)result->major_status, (int)result->minor_status);
 
 	return (TRUE);
 }
@@ -730,6 +804,8 @@ gssd_display_status_1_svc(display_status_args *argp, display_status_res *result,
 	result->major_status = gss_display_status(&result->minor_status,
 	    argp->status_value, argp->status_type, argp->mech_type,
 	    &result->message_context, &result->status_string);
+	gssd_verbose_out("gssd_display_status: done major=0x%x minor=%d\n",
+	    (unsigned int)result->major_status, (int)result->minor_status);
 
 	return (TRUE);
 }