[NFS][PATCH] Adding debugging to svcauth_gss

[Steve Dickson <SteveD@redhat.com>]

[-- Attachment #1: Type: text/plain, Size: 337 bytes --]

While debugging NFS using krb5 auth, I found the following
debugging statements very useful. You'll notice most of the new
dprintks are covered by if statements so they are not nosily,
but they do show where and how errors are being processed
or drop which was invaluable...

 Please consider adding this patch to upstream....

steved.


[-- Attachment #2: linux-2.6.10-nfsd-svcauthgssdb.patch --]
[-- Type: text/x-patch, Size: 4830 bytes --]

--- linux-2.6.9/net/sunrpc/auth_gss/svcauth_gss.c.orig	2004-10-18 17:54:07.000000000 -0400
+++ linux-2.6.9/net/sunrpc/auth_gss/svcauth_gss.c	2005-02-13 21:35:14.000000000 -0500
@@ -455,14 +455,20 @@ gss_svc_searchbyctx(struct xdr_netobj *h
 	struct rsc *found;
 
 	memset(&rsci, 0, sizeof(rsci));
-	if (dup_to_netobj(&rsci.handle, handle->data, handle->len))
+	if (dup_to_netobj(&rsci.handle, handle->data, handle->len)) {
+		dprintk("RPC:      gss_svc_searchbyctx: dup_to_netobj\n");
 		return NULL;
+	}
 	found = rsc_lookup(&rsci, 0);
 	rsc_free(&rsci);
-	if (!found)
+	if (!found) {
+		dprintk("RPC:      gss_svc_searchbyctx: !found\n");
 		return NULL;
-	if (cache_check(&rsc_cache, &found->h, NULL))
+	}
+	if (cache_check(&rsc_cache, &found->h, NULL)) {
+		dprintk("RPC:      gss_svc_searchbyctx: cache_check\n");
 		return NULL;
+	}
 	return found;
 }
 
@@ -555,21 +561,28 @@ gss_verify_header(struct svc_rqst *rqstp
 	iov.iov_base = rpcstart;
 	iov.iov_len = (u8 *)argv->iov_base - (u8 *)rpcstart;
 	xdr_buf_from_iov(&iov, &rpchdr);
+	dprintk("RPC:      svcauth_gss: rpcstart\n");
 
 	*authp = rpc_autherr_badverf;
-	if (argv->iov_len < 4)
+	if (argv->iov_len < 4) {
+		dprintk("RPC:      svcauth_gss: iov_len %d\n", argv->iov_len);
 		return SVC_DENIED;
+	}
 	flavor = ntohl(svc_getu32(argv));
-	if (flavor != RPC_AUTH_GSS)
+	if (flavor != RPC_AUTH_GSS) {
+		dprintk("RPC:      svcauth_gss: flavor %d\n", flavor);
 		return SVC_DENIED;
-	if (svc_safe_getnetobj(argv, &checksum))
+	}
+	if (svc_safe_getnetobj(argv, &checksum)) {
+		dprintk("RPC:      svcauth_gss: svc_safe_getnetobj\n");
 		return SVC_DENIED;
-
+	}
 	if (rqstp->rq_deferred) /* skip verification of revisited request */
 		return SVC_OK;
 	if (gss_verify_mic(ctx_id, &rpchdr, &checksum, NULL)
 							!= GSS_S_COMPLETE) {
 		*authp = rpcsec_gsserr_credproblem;
+		dprintk("RPC:      svcauth_gss: verification of revisited request\n");
 		return SVC_DENIED;
 	}
 
@@ -758,8 +771,10 @@ svcauth_gss_accept(struct svc_rqst *rqst
 	*authp = rpc_autherr_badcred;
 	if (!svcdata)
 		svcdata = kmalloc(sizeof(*svcdata), GFP_KERNEL);
-	if (!svcdata)
+	if (!svcdata) {
+		dprintk("RPC:      SVCauth_gss: kmalloc()\n");
 		goto auth_err;
+	}
 	rqstp->rq_auth_data = svcdata;
 	svcdata->body_start = NULL;
 	svcdata->rsci = NULL;
@@ -770,6 +785,7 @@ svcauth_gss_accept(struct svc_rqst *rqst
 	 */
 	rpcstart = argv->iov_base;
 	rpcstart -= 7;
+	dprintk("RPC:      svcauth_gss: rpcstart 0x%p\n",rpcstart);
 
 	/* credential is:
 	 *   version(==1), proc(0,1,2,3), seq, service (1,2,3), handle
@@ -803,6 +819,7 @@ svcauth_gss_accept(struct svc_rqst *rqst
 	 *   6 (AUTH_RPCSEC_GSS), length, checksum.
 	 * checksum is calculated over rpcheader from xid up to here.
 	 */
+	dprintk("RPC:      svcauth_gss: gc_proc %d\n",gc->gc_proc);
 	*authp = rpc_autherr_badverf;
 	switch (gc->gc_proc) {
 	case RPC_GSS_PROC_INIT:
@@ -818,14 +835,18 @@ svcauth_gss_accept(struct svc_rqst *rqst
 	case RPC_GSS_PROC_DESTROY:
 		*authp = rpcsec_gsserr_credproblem;
 		rsci = gss_svc_searchbyctx(&gc->gc_ctx);
-		if (!rsci)
+		if (!rsci) {
+			dprintk("RPC:      svcauth_gss: gss_svc_searchbyctx\n");
 			goto auth_err;
+		}
 		switch (gss_verify_header(rqstp, rsci, rpcstart, gc, authp)) {
 		case SVC_OK:
 			break;
 		case SVC_DENIED:
+			dprintk("RPC:      svcauth_gss: gss_verify_header DENIED\n");
 			goto auth_err;
 		case SVC_DROP:
+			dprintk("RPC:      svcauth_gss: gss_verify_header DROP\n");
 			goto drop;
 		}
 		break;
@@ -834,6 +855,7 @@ svcauth_gss_accept(struct svc_rqst *rqst
 		goto auth_err;
 	}
 
+	dprintk("RPC:      svcauth_gss: act gc_proc %d\n",gc->gc_proc);
 	/* now act upon the command: */
 	switch (gc->gc_proc) {
 	case RPC_GSS_PROC_INIT:
@@ -861,8 +883,10 @@ svcauth_gss_accept(struct svc_rqst *rqst
 		}
 		switch(cache_check(&rsi_cache, &rsip->h, &rqstp->rq_chandle)) {
 		case -EAGAIN:
+			dprintk("RPC:      svcauth_gss: cache_check -EAGAIN\n");
 			goto drop;
 		case -ENOENT:
+			dprintk("RPC:      svcauth_gss: cache_check -ENOENT\n");
 			goto drop;
 		case 0:
 			rsci = gss_svc_searchbyctx(&rsip->out_handle);
@@ -904,6 +928,7 @@ svcauth_gss_accept(struct svc_rqst *rqst
 		rqstp->rq_cred = rsci->cred;
 		get_group_info(rsci->cred.cr_group_info);
 		*authp = rpc_autherr_badcred;
+		dprintk("RPC:      svcauth_gss: rpc_autherr_badcred %d\n",gc->gc_proc);
 		switch (gc->gc_svc) {
 		case RPC_GSS_SVC_NONE:
 			break;
@@ -928,13 +953,16 @@ svcauth_gss_accept(struct svc_rqst *rqst
 	}
 auth_err:
 	/* Restore write pointer to original value: */
+	dprintk("RPC:      svcauth_gss: auth_err\n");
 	xdr_ressize_check(rqstp, reject_stat);
 	ret = SVC_DENIED;
 	goto out;
 complete:
+	dprintk("RPC:      svcauth_gss: complete\n");
 	ret = SVC_COMPLETE;
 	goto out;
 drop:
+	dprintk("RPC:      svcauth_gss: drop\n");
 	ret = SVC_DROP;
 out:
 	if (rsci)