[PATCH] gssd: Cleaned up debug messages

[PATCH] gssd: Cleaned up debug messages

[Steve Dickson]

Added tids to a number of statements
Broke the lifetime_rec secs into a readable format
Printed tids out correctly
Trim down the output of both '-v' and '-vv'

Signed-off-by: Steve Dickson <steved@redhat.com>
---
 utils/gssd/err_util.c  | 14 ++++++++++++++
 utils/gssd/err_util.h  |  1 +
 utils/gssd/gssd.c      | 12 ++++++------
 utils/gssd/gssd_proc.c | 34 ++++++++++++++++++++++------------
 utils/gssd/krb5_util.c | 29 +++++++++++++++++------------
 5 files changed, 60 insertions(+), 30 deletions(-)

diff --git a/utils/gssd/err_util.c b/utils/gssd/err_util.c
index 2b1132ac..27abd236 100644
--- a/utils/gssd/err_util.c
+++ b/utils/gssd/err_util.c
@@ -70,3 +70,17 @@ int get_verbosity(void)
 {
 	return verbosity;
 }
+
+char * 
+sec2time(int value)
+{
+    static char buf[BUFSIZ];
+    int hr, min, sec;
+
+    hr = (value / 3600);
+    min = (value  - (3600*hr))/60;
+    sec = (value  - (3600*hr) - (min*60));
+    sprintf(buf, "%dh:%dm:%ds", hr, min, sec);
+    return(buf);
+}
+
diff --git a/utils/gssd/err_util.h b/utils/gssd/err_util.h
index c4df32da..6fa9d3d7 100644
--- a/utils/gssd/err_util.h
+++ b/utils/gssd/err_util.h
@@ -34,5 +34,6 @@
 void initerr(char *progname, int verbosity, int fg);
 void printerr(int priority, char *format, ...);
 int get_verbosity(void);
+char * sec2time(int);
 
 #endif /* _ERR_UTIL_H_ */
diff --git a/utils/gssd/gssd.c b/utils/gssd/gssd.c
index 4ca637f4..4113cbab 100644
--- a/utils/gssd/gssd.c
+++ b/utils/gssd/gssd.c
@@ -396,7 +396,7 @@ gssd_free_client(struct clnt_info *clp)
 	if (refcnt > 0)
 		return;
 
-	printerr(3, "freeing client %s\n", clp->relpath);
+	printerr(4, "freeing client %s\n", clp->relpath);
 
 	if (clp->krb5_fd >= 0)
 		close(clp->krb5_fd);
@@ -417,7 +417,7 @@ gssd_free_client(struct clnt_info *clp)
 static void
 gssd_destroy_client(struct clnt_info *clp)
 {
-	printerr(3, "destroying client %s\n", clp->relpath);
+	printerr(4, "destroying client %s\n", clp->relpath);
 
 	if (clp->krb5_ev) {
 		event_del(clp->krb5_ev);
@@ -494,7 +494,7 @@ scan_active_thread_list(void)
 			 * upcall_thread_info from the list and free it.
 			 */
 			if (tret == PTHREAD_CANCELED)
-				printerr(3, "watchdog: thread id 0x%lx cancelled successfully\n",
+				printerr(2, "watchdog: thread id 0x%lx cancelled successfully\n",
 						info->tid);
 			saveprev = info->list.tqe_prev;
 			TAILQ_REMOVE(&active_thread_list, info, list);
@@ -598,7 +598,7 @@ gssd_get_clnt(struct topdir *tdi, const char *name)
 		if (!strcmp(clp->name, name))
 			return clp;
 
-	printerr(3, "creating client %s/%s\n", tdi->name, name);
+	printerr(4, "creating client %s/%s\n", tdi->name, name);
 
 	clp = calloc(1, sizeof(struct clnt_info));
 	if (!clp) {
@@ -639,7 +639,7 @@ gssd_scan_clnt(struct clnt_info *clp)
 {
 	int clntfd;
 
-	printerr(3, "scanning client %s\n", clp->relpath);
+	printerr(4, "scanning client %s\n", clp->relpath);
 
 	clntfd = openat(pipefs_fd, clp->relpath, O_RDONLY);
 	if (clntfd < 0) {
@@ -798,7 +798,7 @@ gssd_scan(void)
 {
 	struct dirent *d;
 
-	printerr(3, "doing a full rescan\n");
+	printerr(4, "doing a full rescan\n");
 	rewinddir(pipefs_dir);
 
 	while ((d = readdir(pipefs_dir))) {
diff --git a/utils/gssd/gssd_proc.c b/utils/gssd/gssd_proc.c
index e849d104..ae568f15 100644
--- a/utils/gssd/gssd_proc.c
+++ b/utils/gssd/gssd_proc.c
@@ -166,8 +166,9 @@ do_downcall(int k5_fd, uid_t uid, struct authgss_private_data *pd,
 	unsigned int buf_size = 0;
 	pthread_t tid = pthread_self();
 
-	printerr(2, "do_downcall(0x%x): lifetime_rec=%u acceptor=%.*s\n",
-		tid, lifetime_rec, acceptor->length, acceptor->value);
+	if (get_verbosity() > 1)
+		printerr(2, "do_downcall(0x%lx): lifetime_rec=%s acceptor=%.*s\n",
+			tid, sec2time(lifetime_rec), acceptor->length, acceptor->value);
 	buf_size = sizeof(uid) + sizeof(timeout) + sizeof(pd->pd_seq_win) +
 		sizeof(pd->pd_ctx_hndl.length) + pd->pd_ctx_hndl.length +
 		sizeof(context_token->length) + context_token->length +
@@ -193,7 +194,7 @@ do_downcall(int k5_fd, uid_t uid, struct authgss_private_data *pd,
 	return;
 out_err:
 	free(buf);
-	printerr(1, "do_downcall(0x%x): Failed to write downcall!\n", tid);
+	printerr(1, "do_downcall(0x%lx): Failed to write downcall!\n", tid);
 	return;
 }
 
@@ -204,8 +205,9 @@ do_error_downcall(int k5_fd, uid_t uid, int err)
 	char	*p = buf, *end = buf + 1024;
 	unsigned int timeout = 0;
 	int	zero = 0;
+	pthread_t tid = pthread_self();
 
-	printerr(2, "doing error downcall\n");
+	printerr(2, "do_error_downcall(0x%lx): uid %d err %d\n", tid, uid, err);
 
 	if (WRITE_BYTES(&p, end, uid)) goto out_err;
 	if (WRITE_BYTES(&p, end, timeout)) goto out_err;
@@ -328,6 +330,7 @@ create_auth_rpc_client(struct clnt_info *clp,
 	struct timeval	timeout;
 	struct sockaddr		*addr = (struct sockaddr *) &clp->addr;
 	socklen_t		salen;
+	pthread_t tid = pthread_self();
 
 	sec.qop = GSS_C_QOP_DEFAULT;
 	sec.svc = RPCSEC_GSS_SVC_NONE;
@@ -361,8 +364,8 @@ create_auth_rpc_client(struct clnt_info *clp,
 
 	/* create an rpc connection to the nfs server */
 
-	printerr(2, "creating %s client for server %s\n", clp->protocol,
-			clp->servername);
+	printerr(3, "create_auth_rpc_client(0x%lx): creating %s client for server %s\n", 
+		tid, clp->protocol, clp->servername);
 
 	protocol = IPPROTO_TCP;
 	if ((strcmp(clp->protocol, "udp")) == 0)
@@ -405,7 +408,8 @@ create_auth_rpc_client(struct clnt_info *clp,
 	if (!tgtname)
 		tgtname = clp->servicename;
 
-	printerr(2, "creating context with server %s\n", tgtname);
+	printerr(3, "create_auth_rpc_client(0x%lx): creating context with server %s\n", 
+		tid, tgtname);
 	auth = authgss_create_default(rpc_clnt, tgtname, &sec);
 	if (!auth) {
 		/* Our caller should print appropriate message */
@@ -511,9 +515,10 @@ krb5_not_machine_creds(struct clnt_info *clp, uid_t uid, char *tgtname,
 	gss_cred_id_t	gss_cred;
 	char		**dname;
 	int		err, resp = -1;
+	pthread_t tid = pthread_self();
 
-	printerr(2, "krb5_not_machine_creds: uid %d tgtname %s\n", 
-		uid, tgtname);
+	printerr(2, "krb5_not_machine_creds(0x%lx): uid %d tgtname %s\n", 
+		tid, uid, tgtname);
 
 	*chg_err = change_identity(uid);
 	if (*chg_err) {
@@ -559,9 +564,10 @@ krb5_use_machine_creds(struct clnt_info *clp, uid_t uid,
 	char	**ccname;
 	int	nocache = 0;
 	int	success = 0;
+	pthread_t tid = pthread_self();
 
-	printerr(2, "krb5_use_machine_creds: uid %d tgtname %s\n", 
-		uid, tgtname);
+	printerr(2, "krb5_use_machine_creds(0x%lx): uid %d tgtname %s\n", 
+		tid, uid, tgtname);
 
 	do {
 		gssd_refresh_krb5_machine_credential(clp->servername,
@@ -878,6 +884,7 @@ start_upcall_thread(void (*func)(struct clnt_upcall_info *), struct clnt_upcall_
 	pthread_t th;
 	struct upcall_thread_info *tinfo;
 	int ret;
+	pthread_t tid = pthread_self();
 
 	tinfo = alloc_upcall_thread_info();
 	if (!tinfo)
@@ -900,6 +907,9 @@ start_upcall_thread(void (*func)(struct clnt_upcall_info *), struct clnt_upcall_
 		free(tinfo);
 		return ret;
 	}
+	printerr(2, "start_upcall_thread(0x%lx): created thread id 0x%lx\n", 
+		tid, th);
+
 	tinfo->tid = th;
 	pthread_mutex_lock(&active_thread_list_lock);
 	clock_gettime(CLOCK_MONOTONIC, &tinfo->timeout);
@@ -962,7 +972,7 @@ handle_gssd_upcall(struct clnt_info *clp)
 	}
 	lbuf[lbuflen-1] = 0;
 
-	printerr(2, "\n%s(0x%x): '%s' (%s)\n", __func__, tid,
+	printerr(2, "\n%s(0x%lx): '%s' (%s)\n", __func__, tid,
 		 lbuf, clp->relpath);
 
 	for (p = strtok(lbuf, " "); p; p = strtok(NULL, " ")) {
diff --git a/utils/gssd/krb5_util.c b/utils/gssd/krb5_util.c
index 51e0c6a2..c5f1152e 100644
--- a/utils/gssd/krb5_util.c
+++ b/utils/gssd/krb5_util.c
@@ -409,6 +409,7 @@ gssd_get_single_krb5_cred(krb5_context context,
 	char *pname = NULL;
 	char *k5err = NULL;
 	int nocache = 0;
+	pthread_t tid = pthread_self();
 
 	memset(&my_creds, 0, sizeof(my_creds));
 
@@ -421,8 +422,8 @@ gssd_get_single_krb5_cred(krb5_context context,
 	now += 300;
 	pthread_mutex_lock(&ple_lock);
 	if (ple->ccname && ple->endtime > now && !nocache) {
-		printerr(3, "INFO: Credentials in CC '%s' are good until %d\n",
-			 ple->ccname, ple->endtime);
+		printerr(3, "%s(0x%lx): Credentials in CC '%s' are good until %s",
+			 __func__, tid, ple->ccname, ctime((time_t *)&ple->endtime));
 		code = 0;
 		pthread_mutex_unlock(&ple_lock);
 		goto out;
@@ -522,7 +523,8 @@ gssd_get_single_krb5_cred(krb5_context context,
 	}
 
 	code = 0;
-	printerr(2, "%s: principal '%s' ccache:'%s'\n", __func__, pname, cc_name);
+	printerr(2, "%s(0x%lx): principal '%s' ccache:'%s'\n", 
+		__func__, tid, pname, cc_name);
   out:
 #ifdef HAVE_KRB5_GET_INIT_CREDS_OPT_SET_ADDRESSLESS
 	if (init_opts)
@@ -651,6 +653,7 @@ get_full_hostname(const char *inhost, char *outhost, int outhostlen)
 	struct addrinfo hints;
 	int retval;
 	char *c;
+	pthread_t tid = pthread_self();
 
 	memset(&hints, 0, sizeof(hints));
 	hints.ai_socktype = SOCK_STREAM;
@@ -660,8 +663,8 @@ get_full_hostname(const char *inhost, char *outhost, int outhostlen)
 	/* Get full target hostname */
 	retval = getaddrinfo(inhost, NULL, &hints, &addrs);
 	if (retval) {
-		printerr(1, "%s while getting full hostname for '%s'\n",
-			 gai_strerror(retval), inhost);
+		printerr(1, "%s(0x%lx): getaddrinfo(%s) failed: %s\n",
+			 __func__, tid, inhost, gai_strerror(retval));
 		goto out;
 	}
 	strncpy(outhost, addrs->ai_canonname, outhostlen);
@@ -669,7 +672,10 @@ get_full_hostname(const char *inhost, char *outhost, int outhostlen)
 	for (c = outhost; *c != '\0'; c++)
 	    *c = tolower(*c);
 
-	printerr(3, "Full hostname for '%s' is '%s'\n", inhost, outhost);
+	if (get_verbosity() && strcmp(inhost, outhost))
+		printerr(1, "%s(0x%0lx): inhost '%s' different than outhost'%s'\n", 
+			inhost, outhost);
+
 	retval = 0;
 out:
 	return retval;
@@ -856,6 +862,7 @@ find_keytab_entry(krb5_context context, krb5_keytab kt,
 	krb5_principal princ;
 	const char *notsetstr = "not set";
 	char *adhostoverride = NULL;
+	pthread_t tid = pthread_self();
 
 
 	/* Get full target hostname */
@@ -1010,7 +1017,7 @@ find_keytab_entry(krb5_context context, krb5_keytab kt,
 					tried_upper = 1;
 				}
 			} else {
-				printerr(2, "Success getting keytab entry for '%s'\n",spn);
+				printerr(2, "find_keytab_entry(0x%lx): Success getting keytab entry for '%s'\n",tid, spn);
 				retval = 0;
 				goto out;
 			}
@@ -1151,9 +1158,6 @@ gssd_refresh_krb5_machine_credential_internal(char *hostname,
 	char *k5err = NULL;
 	const char *svcnames[] = { "$", "root", "nfs", "host", NULL };
 
-	printerr(2, "%s: hostname=%s ple=%p service=%s srchost=%s\n",
-		__func__, hostname, ple, service, srchost);
-
 	/*
 	 * If a specific service name was specified, use it.
 	 * Otherwise, use the default list.
@@ -1162,9 +1166,10 @@ gssd_refresh_krb5_machine_credential_internal(char *hostname,
 		svcnames[0] = service;
 		svcnames[1] = NULL;
 	}
-	if (hostname == NULL && ple == NULL)
+	if (hostname == NULL && ple == NULL) {
+		printerr(0, "ERROR: %s: Invalid args\n", __func__);
 		return EINVAL;
-
+	}
 	code = krb5_init_context(&context);
 	if (code) {
 		k5err = gssd_k5_err_msg(NULL, code);
-- 
2.31.1

Re: [PATCH] gssd: Cleaned up debug messages

[Steve Dickson]

On 6/10/21 11:08 AM, Steve Dickson wrote:
> Added tids to a number of statements
> Broke the lifetime_rec secs into a readable format
> Printed tids out correctly
> Trim down the output of both '-v' and '-vv'
> 
> Signed-off-by: Steve Dickson <steved@redhat.com>
Committed (tag: nfs-utils-2-5-4-rc7)

steved.
> ---
>   utils/gssd/err_util.c  | 14 ++++++++++++++
>   utils/gssd/err_util.h  |  1 +
>   utils/gssd/gssd.c      | 12 ++++++------
>   utils/gssd/gssd_proc.c | 34 ++++++++++++++++++++++------------
>   utils/gssd/krb5_util.c | 29 +++++++++++++++++------------
>   5 files changed, 60 insertions(+), 30 deletions(-)
> 
> diff --git a/utils/gssd/err_util.c b/utils/gssd/err_util.c
> index 2b1132ac..27abd236 100644
> --- a/utils/gssd/err_util.c
> +++ b/utils/gssd/err_util.c
> @@ -70,3 +70,17 @@ int get_verbosity(void)
>   {
>   	return verbosity;
>   }
> +
> +char *
> +sec2time(int value)
> +{
> +    static char buf[BUFSIZ];
> +    int hr, min, sec;
> +
> +    hr = (value / 3600);
> +    min = (value  - (3600*hr))/60;
> +    sec = (value  - (3600*hr) - (min*60));
> +    sprintf(buf, "%dh:%dm:%ds", hr, min, sec);
> +    return(buf);
> +}
> +
> diff --git a/utils/gssd/err_util.h b/utils/gssd/err_util.h
> index c4df32da..6fa9d3d7 100644
> --- a/utils/gssd/err_util.h
> +++ b/utils/gssd/err_util.h
> @@ -34,5 +34,6 @@
>   void initerr(char *progname, int verbosity, int fg);
>   void printerr(int priority, char *format, ...);
>   int get_verbosity(void);
> +char * sec2time(int);
>   
>   #endif /* _ERR_UTIL_H_ */
> diff --git a/utils/gssd/gssd.c b/utils/gssd/gssd.c
> index 4ca637f4..4113cbab 100644
> --- a/utils/gssd/gssd.c
> +++ b/utils/gssd/gssd.c
> @@ -396,7 +396,7 @@ gssd_free_client(struct clnt_info *clp)
>   	if (refcnt > 0)
>   		return;
>   
> -	printerr(3, "freeing client %s\n", clp->relpath);
> +	printerr(4, "freeing client %s\n", clp->relpath);
>   
>   	if (clp->krb5_fd >= 0)
>   		close(clp->krb5_fd);
> @@ -417,7 +417,7 @@ gssd_free_client(struct clnt_info *clp)
>   static void
>   gssd_destroy_client(struct clnt_info *clp)
>   {
> -	printerr(3, "destroying client %s\n", clp->relpath);
> +	printerr(4, "destroying client %s\n", clp->relpath);
>   
>   	if (clp->krb5_ev) {
>   		event_del(clp->krb5_ev);
> @@ -494,7 +494,7 @@ scan_active_thread_list(void)
>   			 * upcall_thread_info from the list and free it.
>   			 */
>   			if (tret == PTHREAD_CANCELED)
> -				printerr(3, "watchdog: thread id 0x%lx cancelled successfully\n",
> +				printerr(2, "watchdog: thread id 0x%lx cancelled successfully\n",
>   						info->tid);
>   			saveprev = info->list.tqe_prev;
>   			TAILQ_REMOVE(&active_thread_list, info, list);
> @@ -598,7 +598,7 @@ gssd_get_clnt(struct topdir *tdi, const char *name)
>   		if (!strcmp(clp->name, name))
>   			return clp;
>   
> -	printerr(3, "creating client %s/%s\n", tdi->name, name);
> +	printerr(4, "creating client %s/%s\n", tdi->name, name);
>   
>   	clp = calloc(1, sizeof(struct clnt_info));
>   	if (!clp) {
> @@ -639,7 +639,7 @@ gssd_scan_clnt(struct clnt_info *clp)
>   {
>   	int clntfd;
>   
> -	printerr(3, "scanning client %s\n", clp->relpath);
> +	printerr(4, "scanning client %s\n", clp->relpath);
>   
>   	clntfd = openat(pipefs_fd, clp->relpath, O_RDONLY);
>   	if (clntfd < 0) {
> @@ -798,7 +798,7 @@ gssd_scan(void)
>   {
>   	struct dirent *d;
>   
> -	printerr(3, "doing a full rescan\n");
> +	printerr(4, "doing a full rescan\n");
>   	rewinddir(pipefs_dir);
>   
>   	while ((d = readdir(pipefs_dir))) {
> diff --git a/utils/gssd/gssd_proc.c b/utils/gssd/gssd_proc.c
> index e849d104..ae568f15 100644
> --- a/utils/gssd/gssd_proc.c
> +++ b/utils/gssd/gssd_proc.c
> @@ -166,8 +166,9 @@ do_downcall(int k5_fd, uid_t uid, struct authgss_private_data *pd,
>   	unsigned int buf_size = 0;
>   	pthread_t tid = pthread_self();
>   
> -	printerr(2, "do_downcall(0x%x): lifetime_rec=%u acceptor=%.*s\n",
> -		tid, lifetime_rec, acceptor->length, acceptor->value);
> +	if (get_verbosity() > 1)
> +		printerr(2, "do_downcall(0x%lx): lifetime_rec=%s acceptor=%.*s\n",
> +			tid, sec2time(lifetime_rec), acceptor->length, acceptor->value);
>   	buf_size = sizeof(uid) + sizeof(timeout) + sizeof(pd->pd_seq_win) +
>   		sizeof(pd->pd_ctx_hndl.length) + pd->pd_ctx_hndl.length +
>   		sizeof(context_token->length) + context_token->length +
> @@ -193,7 +194,7 @@ do_downcall(int k5_fd, uid_t uid, struct authgss_private_data *pd,
>   	return;
>   out_err:
>   	free(buf);
> -	printerr(1, "do_downcall(0x%x): Failed to write downcall!\n", tid);
> +	printerr(1, "do_downcall(0x%lx): Failed to write downcall!\n", tid);
>   	return;
>   }
>   
> @@ -204,8 +205,9 @@ do_error_downcall(int k5_fd, uid_t uid, int err)
>   	char	*p = buf, *end = buf + 1024;
>   	unsigned int timeout = 0;
>   	int	zero = 0;
> +	pthread_t tid = pthread_self();
>   
> -	printerr(2, "doing error downcall\n");
> +	printerr(2, "do_error_downcall(0x%lx): uid %d err %d\n", tid, uid, err);
>   
>   	if (WRITE_BYTES(&p, end, uid)) goto out_err;
>   	if (WRITE_BYTES(&p, end, timeout)) goto out_err;
> @@ -328,6 +330,7 @@ create_auth_rpc_client(struct clnt_info *clp,
>   	struct timeval	timeout;
>   	struct sockaddr		*addr = (struct sockaddr *) &clp->addr;
>   	socklen_t		salen;
> +	pthread_t tid = pthread_self();
>   
>   	sec.qop = GSS_C_QOP_DEFAULT;
>   	sec.svc = RPCSEC_GSS_SVC_NONE;
> @@ -361,8 +364,8 @@ create_auth_rpc_client(struct clnt_info *clp,
>   
>   	/* create an rpc connection to the nfs server */
>   
> -	printerr(2, "creating %s client for server %s\n", clp->protocol,
> -			clp->servername);
> +	printerr(3, "create_auth_rpc_client(0x%lx): creating %s client for server %s\n",
> +		tid, clp->protocol, clp->servername);
>   
>   	protocol = IPPROTO_TCP;
>   	if ((strcmp(clp->protocol, "udp")) == 0)
> @@ -405,7 +408,8 @@ create_auth_rpc_client(struct clnt_info *clp,
>   	if (!tgtname)
>   		tgtname = clp->servicename;
>   
> -	printerr(2, "creating context with server %s\n", tgtname);
> +	printerr(3, "create_auth_rpc_client(0x%lx): creating context with server %s\n",
> +		tid, tgtname);
>   	auth = authgss_create_default(rpc_clnt, tgtname, &sec);
>   	if (!auth) {
>   		/* Our caller should print appropriate message */
> @@ -511,9 +515,10 @@ krb5_not_machine_creds(struct clnt_info *clp, uid_t uid, char *tgtname,
>   	gss_cred_id_t	gss_cred;
>   	char		**dname;
>   	int		err, resp = -1;
> +	pthread_t tid = pthread_self();
>   
> -	printerr(2, "krb5_not_machine_creds: uid %d tgtname %s\n",
> -		uid, tgtname);
> +	printerr(2, "krb5_not_machine_creds(0x%lx): uid %d tgtname %s\n",
> +		tid, uid, tgtname);
>   
>   	*chg_err = change_identity(uid);
>   	if (*chg_err) {
> @@ -559,9 +564,10 @@ krb5_use_machine_creds(struct clnt_info *clp, uid_t uid,
>   	char	**ccname;
>   	int	nocache = 0;
>   	int	success = 0;
> +	pthread_t tid = pthread_self();
>   
> -	printerr(2, "krb5_use_machine_creds: uid %d tgtname %s\n",
> -		uid, tgtname);
> +	printerr(2, "krb5_use_machine_creds(0x%lx): uid %d tgtname %s\n",
> +		tid, uid, tgtname);
>   
>   	do {
>   		gssd_refresh_krb5_machine_credential(clp->servername,
> @@ -878,6 +884,7 @@ start_upcall_thread(void (*func)(struct clnt_upcall_info *), struct clnt_upcall_
>   	pthread_t th;
>   	struct upcall_thread_info *tinfo;
>   	int ret;
> +	pthread_t tid = pthread_self();
>   
>   	tinfo = alloc_upcall_thread_info();
>   	if (!tinfo)
> @@ -900,6 +907,9 @@ start_upcall_thread(void (*func)(struct clnt_upcall_info *), struct clnt_upcall_
>   		free(tinfo);
>   		return ret;
>   	}
> +	printerr(2, "start_upcall_thread(0x%lx): created thread id 0x%lx\n",
> +		tid, th);
> +
>   	tinfo->tid = th;
>   	pthread_mutex_lock(&active_thread_list_lock);
>   	clock_gettime(CLOCK_MONOTONIC, &tinfo->timeout);
> @@ -962,7 +972,7 @@ handle_gssd_upcall(struct clnt_info *clp)
>   	}
>   	lbuf[lbuflen-1] = 0;
>   
> -	printerr(2, "\n%s(0x%x): '%s' (%s)\n", __func__, tid,
> +	printerr(2, "\n%s(0x%lx): '%s' (%s)\n", __func__, tid,
>   		 lbuf, clp->relpath);
>   
>   	for (p = strtok(lbuf, " "); p; p = strtok(NULL, " ")) {
> diff --git a/utils/gssd/krb5_util.c b/utils/gssd/krb5_util.c
> index 51e0c6a2..c5f1152e 100644
> --- a/utils/gssd/krb5_util.c
> +++ b/utils/gssd/krb5_util.c
> @@ -409,6 +409,7 @@ gssd_get_single_krb5_cred(krb5_context context,
>   	char *pname = NULL;
>   	char *k5err = NULL;
>   	int nocache = 0;
> +	pthread_t tid = pthread_self();
>   
>   	memset(&my_creds, 0, sizeof(my_creds));
>   
> @@ -421,8 +422,8 @@ gssd_get_single_krb5_cred(krb5_context context,
>   	now += 300;
>   	pthread_mutex_lock(&ple_lock);
>   	if (ple->ccname && ple->endtime > now && !nocache) {
> -		printerr(3, "INFO: Credentials in CC '%s' are good until %d\n",
> -			 ple->ccname, ple->endtime);
> +		printerr(3, "%s(0x%lx): Credentials in CC '%s' are good until %s",
> +			 __func__, tid, ple->ccname, ctime((time_t *)&ple->endtime));
>   		code = 0;
>   		pthread_mutex_unlock(&ple_lock);
>   		goto out;
> @@ -522,7 +523,8 @@ gssd_get_single_krb5_cred(krb5_context context,
>   	}
>   
>   	code = 0;
> -	printerr(2, "%s: principal '%s' ccache:'%s'\n", __func__, pname, cc_name);
> +	printerr(2, "%s(0x%lx): principal '%s' ccache:'%s'\n",
> +		__func__, tid, pname, cc_name);
>     out:
>   #ifdef HAVE_KRB5_GET_INIT_CREDS_OPT_SET_ADDRESSLESS
>   	if (init_opts)
> @@ -651,6 +653,7 @@ get_full_hostname(const char *inhost, char *outhost, int outhostlen)
>   	struct addrinfo hints;
>   	int retval;
>   	char *c;
> +	pthread_t tid = pthread_self();
>   
>   	memset(&hints, 0, sizeof(hints));
>   	hints.ai_socktype = SOCK_STREAM;
> @@ -660,8 +663,8 @@ get_full_hostname(const char *inhost, char *outhost, int outhostlen)
>   	/* Get full target hostname */
>   	retval = getaddrinfo(inhost, NULL, &hints, &addrs);
>   	if (retval) {
> -		printerr(1, "%s while getting full hostname for '%s'\n",
> -			 gai_strerror(retval), inhost);
> +		printerr(1, "%s(0x%lx): getaddrinfo(%s) failed: %s\n",
> +			 __func__, tid, inhost, gai_strerror(retval));
>   		goto out;
>   	}
>   	strncpy(outhost, addrs->ai_canonname, outhostlen);
> @@ -669,7 +672,10 @@ get_full_hostname(const char *inhost, char *outhost, int outhostlen)
>   	for (c = outhost; *c != '\0'; c++)
>   	    *c = tolower(*c);
>   
> -	printerr(3, "Full hostname for '%s' is '%s'\n", inhost, outhost);
> +	if (get_verbosity() && strcmp(inhost, outhost))
> +		printerr(1, "%s(0x%0lx): inhost '%s' different than outhost'%s'\n",
> +			inhost, outhost);
> +
>   	retval = 0;
>   out:
>   	return retval;
> @@ -856,6 +862,7 @@ find_keytab_entry(krb5_context context, krb5_keytab kt,
>   	krb5_principal princ;
>   	const char *notsetstr = "not set";
>   	char *adhostoverride = NULL;
> +	pthread_t tid = pthread_self();
>   
>   
>   	/* Get full target hostname */
> @@ -1010,7 +1017,7 @@ find_keytab_entry(krb5_context context, krb5_keytab kt,
>   					tried_upper = 1;
>   				}
>   			} else {
> -				printerr(2, "Success getting keytab entry for '%s'\n",spn);
> +				printerr(2, "find_keytab_entry(0x%lx): Success getting keytab entry for '%s'\n",tid, spn);
>   				retval = 0;
>   				goto out;
>   			}
> @@ -1151,9 +1158,6 @@ gssd_refresh_krb5_machine_credential_internal(char *hostname,
>   	char *k5err = NULL;
>   	const char *svcnames[] = { "$", "root", "nfs", "host", NULL };
>   
> -	printerr(2, "%s: hostname=%s ple=%p service=%s srchost=%s\n",
> -		__func__, hostname, ple, service, srchost);
> -
>   	/*
>   	 * If a specific service name was specified, use it.
>   	 * Otherwise, use the default list.
> @@ -1162,9 +1166,10 @@ gssd_refresh_krb5_machine_credential_internal(char *hostname,
>   		svcnames[0] = service;
>   		svcnames[1] = NULL;
>   	}
> -	if (hostname == NULL && ple == NULL)
> +	if (hostname == NULL && ple == NULL) {
> +		printerr(0, "ERROR: %s: Invalid args\n", __func__);
>   		return EINVAL;
> -
> +	}
>   	code = krb5_init_context(&context);
>   	if (code) {
>   		k5err = gssd_k5_err_msg(NULL, code);
> 

[PATCH] gssd: fix crash in debug message.

[NeilBrown]

A recent cleanup of debug messages added func and tid format specifiers
to a debug message (when full hostname was different), but the func name
and tid were NOT added as arguments.

Consequently there weren't enough args, random bytes of the stack were
interpreted as a pointer, and rpc.gssd crashed (when -v was specified).

Fixes: b538862a5135 ("gssd: Cleaned up debug messages")
Signed-off-by: NeilBrown <neilb@suse.de>
---
 utils/gssd/krb5_util.c | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/utils/gssd/krb5_util.c b/utils/gssd/krb5_util.c
index 6d059f332881..e3f270e948ac 100644
--- a/utils/gssd/krb5_util.c
+++ b/utils/gssd/krb5_util.c
@@ -673,8 +673,8 @@ get_full_hostname(const char *inhost, char *outhost, int outhostlen)
 	    *c = tolower(*c);
 
 	if (get_verbosity() && strcmp(inhost, outhost))
-		printerr(1, "%s(0x%0lx): inhost '%s' different than outhost'%s'\n", 
-			inhost, outhost);
+		printerr(1, "%s(0x%0lx): inhost '%s' different than outhost '%s'\n", 
+			 __func__, tid, inhost, outhost);
 
 	retval = 0;
 out:
-- 
2.33.0

Re: [PATCH] gssd: fix crash in debug message.

[Petr Vorel]

Hi Steve, Neil,

Reviewed-by: Petr Vorel <pvorel@suse.cz>

Kind regards,
Petr

Re: [PATCH] gssd: fix crash in debug message.

[Steve Dickson]

On 9/9/21 1:43 AM, NeilBrown wrote:
> 
> A recent cleanup of debug messages added func and tid format specifiers
> to a debug message (when full hostname was different), but the func name
> and tid were NOT added as arguments.
> 
> Consequently there weren't enough args, random bytes of the stack were
> interpreted as a pointer, and rpc.gssd crashed (when -v was specified).
> 
> Fixes: b538862a5135 ("gssd: Cleaned up debug messages")
> Signed-off-by: NeilBrown <neilb@suse.de>
Committed... (tag: nfs-utils-2-5-5-rc3)

Thanks for the clean up!!

steved.
> ---
>   utils/gssd/krb5_util.c | 4 ++--
>   1 file changed, 2 insertions(+), 2 deletions(-)
> 
> diff --git a/utils/gssd/krb5_util.c b/utils/gssd/krb5_util.c
> index 6d059f332881..e3f270e948ac 100644
> --- a/utils/gssd/krb5_util.c
> +++ b/utils/gssd/krb5_util.c
> @@ -673,8 +673,8 @@ get_full_hostname(const char *inhost, char *outhost, int outhostlen)
>   	    *c = tolower(*c);
>   
>   	if (get_verbosity() && strcmp(inhost, outhost))
> -		printerr(1, "%s(0x%0lx): inhost '%s' different than outhost'%s'\n",
> -			inhost, outhost);
> +		printerr(1, "%s(0x%0lx): inhost '%s' different than outhost '%s'\n",
> +			 __func__, tid, inhost, outhost);
>   
>   	retval = 0;
>   out:
>