RPCSEC_GSS: this adds some new trace messages and

     makes existing ones consistent with other
     trace messages in the RPC client.
                                                                                
Patch by Chuck Lever

net/sunrpc/auth_gss/auth_gss.c

@@ -311,8 +311,10 @@ __gss_find_upcall(struct gss_auth *gss_auth, uid_t uid)
 		if (pos->uid != uid)
 			continue;
 		atomic_inc(&pos->count);
+		dprintk("RPC:      gss_find_upcall found msg %p\n", pos);
 		return pos;
 	}
+	dprintk("RPC:      gss_find_upcall found nothing\n");
 	return NULL;
 }
 
@@ -350,6 +352,8 @@ gss_upcall(struct rpc_clnt *clnt, struct rpc_task *task, struct rpc_cred *cred)
 	uid_t uid = cred->cr_uid;
 	int res = 0;
 
+	dprintk("RPC: %4u gss_upcall for uid %u\n", task->tk_pid, uid);
+
 retry:
 	spin_lock(&gss_auth->lock);
 	gss_msg = __gss_find_upcall(gss_auth, uid);
@@ -358,8 +362,10 @@ gss_upcall(struct rpc_clnt *clnt, struct rpc_task *task, struct rpc_cred *cred)
 	if (gss_new == NULL) {
 		spin_unlock(&gss_auth->lock);
 		gss_new = kmalloc(sizeof(*gss_new), GFP_KERNEL);
-		if (!gss_new)
+		if (!gss_new) {
+			dprintk("RPC: %4u gss_upcall -ENOMEM\n", task->tk_pid);
 			return -ENOMEM;
+		}
 		goto retry;
 	}
 	gss_msg = gss_new;
@@ -389,12 +395,14 @@ gss_upcall(struct rpc_clnt *clnt, struct rpc_task *task, struct rpc_cred *cred)
 		spin_unlock(&gss_auth->lock);
 	}
 	gss_release_msg(gss_msg);
+	dprintk("RPC: %4u gss_upcall for uid %u result %d", task->tk_pid,
+			uid, res);
 	return res;
 out_sleep:
-	/* Sleep forever */
 	task->tk_timeout = 0;
 	rpc_sleep_on(&gss_msg->waitq, task, NULL, NULL);
 	spin_unlock(&gss_auth->lock);
+	dprintk("RPC: %4u gss_upcall  sleeping\n", task->tk_pid);
 	if (gss_new)
 		kfree(gss_new);
 	/* Note: we drop the reference here: we are automatically removed
@@ -477,6 +485,7 @@ gss_pipe_downcall(struct file *filp, const char *src, size_t mlen)
 	} else
 		spin_unlock(&gss_auth->lock);
 	rpc_release_client(clnt);
+	dprintk("RPC:      gss_pipe_downcall returning length %u\n", mlen);
 	return mlen;
 err:
 	if (ctx)
@@ -520,6 +529,8 @@ gss_pipe_destroy_msg(struct rpc_pipe_msg *msg)
 	static unsigned long ratelimit;
 
 	if (msg->errno < 0) {
+		dprintk("RPC:      gss_pipe_destroy_msg releasing msg %p\n",
+				gss_msg);
 		atomic_inc(&gss_msg->count);
 		gss_unhash_msg(gss_msg);
 		if (msg->errno == -ETIMEDOUT || msg->errno == -EPIPE) {
@@ -545,6 +556,7 @@ gss_create(struct rpc_clnt *clnt, rpc_authflavor_t flavor)
 	struct rpc_auth * auth;
 
 	dprintk("RPC:      creating GSS authenticator for client %p\n",clnt);
+
 	if (!(gss_auth = kmalloc(sizeof(*gss_auth), GFP_KERNEL)))
 		goto out_dec;
 	gss_auth->mech = gss_pseudoflavor_to_mech(flavor);
@@ -582,6 +594,7 @@ static void
 gss_destroy(struct rpc_auth *auth)
 {
 	struct gss_auth *gss_auth;
+
 	dprintk("RPC:      destroying GSS authenticator %p flavor %d\n",
 		auth, auth->au_flavor);
 
@@ -597,7 +610,6 @@ gss_destroy(struct rpc_auth *auth)
 static void
 gss_destroy_ctx(struct gss_cl_ctx *ctx)
 {
-
 	dprintk("RPC:      gss_destroy_ctx\n");
 
 	if (ctx->gc_gss_ctx)
@@ -679,15 +691,15 @@ gss_marshal(struct rpc_task *task, u32 *p, int ruid)
 	struct xdr_buf	verf_buf;
 	u32		service;
 
-	dprintk("RPC: gss_marshal\n");
+	dprintk("RPC: %4u gss_marshal\n", task->tk_pid);
 
 	*p++ = htonl(RPC_AUTH_GSS);
 	cred_len = p++;
 
 	service = gss_pseudoflavor_to_service(gss_cred->gc_flavor);
 	if (service == 0) {
-		dprintk("Bad pseudoflavor %d in gss_marshal\n",
-			gss_cred->gc_flavor);
+		dprintk("RPC: %4u Bad pseudoflavor %d in gss_marshal\n",
+			task->tk_pid, gss_cred->gc_flavor);
 		goto out_put_ctx;
 	}
 	spin_lock(&ctx->gc_seq_lock);
@@ -757,7 +769,7 @@ gss_validate(struct rpc_task *task, u32 *p)
 	u32		flav,len;
 	u32		service;
 
-	dprintk("RPC: gss_validate\n");
+	dprintk("RPC: %4u gss_validate\n", task->tk_pid);
 
 	flav = ntohl(*p++);
 	if ((len = ntohl(*p++)) > RPC_MAX_AUTH_SIZE)
@@ -787,9 +799,12 @@ gss_validate(struct rpc_task *task, u32 *p)
 	       goto out_bad;
        }
 	gss_put_ctx(ctx);
+	dprintk("RPC: %4u GSS gss_validate: gss_verify_mic succeeded.\n",
+			task->tk_pid);
 	return p + XDR_QUADLEN(len);
 out_bad:
 	gss_put_ctx(ctx);
+	dprintk("RPC: %4u gss_validate failed.\n", task->tk_pid);
 	return NULL;
 }
 
@@ -812,7 +827,7 @@ gss_wrap_req(struct rpc_task *task,
 	u32		offset, *q;
 	struct iovec	*iov;
 
-	dprintk("RPC: gss_wrap_body\n");
+	dprintk("RPC: %4u gss_wrap_req\n", task->tk_pid);
 	BUG_ON(!ctx);
 	if (ctx->gc_proc != RPC_GSS_PROC_DATA) {
 		/* The spec seems a little ambiguous here, but I think that not
@@ -867,7 +882,7 @@ gss_wrap_req(struct rpc_task *task,
 	status = 0;
 out:
 	gss_put_ctx(ctx);
-	dprintk("RPC: gss_wrap_req returning %d\n", status);
+	dprintk("RPC: %4u gss_wrap_req returning %d\n", task->tk_pid, status);
 	return status;
 }
 
@@ -928,7 +943,8 @@ gss_unwrap_resp(struct rpc_task *task,
 	status = decode(rqstp, p, obj);
 out:
 	gss_put_ctx(ctx);
-	dprintk("RPC: gss_unwrap_resp returning %d\n", status);
+	dprintk("RPC: %4u gss_unwrap_resp returning %d\n", task->tk_pid,
+			status);
 	return status;
 }
   

net/sunrpc/auth_gss/gss_krb5_crypto.c

@@ -84,7 +84,7 @@ krb5_encrypt(
 	dprintk("RPC:      krb5_encrypt: output data:\n");
 	print_hexl((u32 *)out, length, 0);
 out:
-	dprintk("krb5_encrypt returns %d\n",ret);
+	dprintk("RPC:      krb5_encrypt returns %d\n",ret);
 	return(ret);
 }
 
@@ -124,7 +124,7 @@ krb5_decrypt(
 	dprintk("RPC:      krb5_decrypt: output_data:\n");
 	print_hexl((u32 *)out, length, 0);
 out:
-	dprintk("gss_k5decrypt returns %d\n",ret);
+	dprintk("RPC:      gss_k5decrypt returns %d\n",ret);
 	return(ret);
 }
 

net/sunrpc/auth_gss/gss_krb5_mech.c

@@ -155,7 +155,7 @@ gss_import_sec_context_kerberos(struct xdr_netobj *inbuf,
 		goto out_err_free_key2;
 
 	ctx_id->internal_ctx_id = ctx;
-	dprintk("Succesfully imported new context.\n");
+	dprintk("RPC:      Succesfully imported new context.\n");
 	return 0;
 
 out_err_free_key2:

net/sunrpc/auth_gss/gss_krb5_seal.c

@@ -151,7 +151,7 @@ krb5_make_token(struct krb5_ctx *ctx, int qop_req,
 		       md5cksum.data + md5cksum.len - KRB5_CKSUM_LENGTH,
 		       KRB5_CKSUM_LENGTH);
 
-		dprintk("make_seal_token: cksum data: \n");
+		dprintk("RPC:      make_seal_token: cksum data: \n");
 		print_hexl((u32 *) (krb5_hdr + 16), KRB5_CKSUM_LENGTH, 0);
 		break;
 	default:

net/sunrpc/auth_gss/gss_krb5_seqnum.c

@@ -70,7 +70,7 @@ krb5_get_seq_num(struct crypto_tfm *key,
 	s32 code;
 	unsigned char plain[8];
 
-	dprintk("krb5_get_seq_num: \n");
+	dprintk("RPC:      krb5_get_seq_num:\n");
 
 	if ((code = krb5_decrypt(key, cksum, buf, plain, 8)))
 		return code;

net/sunrpc/auth_gss/gss_mech_switch.c

@@ -96,8 +96,7 @@ do_gss_mech_unregister(struct gss_api_mech *gm)
 	dprintk("RPC:      unregistered mechanism with oid:\n");
 	print_hexl((u32 *)gm->gm_oid.data, gm->gm_oid.len, 0);
 	if (!gss_mech_put(gm)) {
-		dprintk("RPC: We just unregistered a gss_mechanism which"
-				" someone is still using.\n");
+		dprintk("RPC:      We just unregistered a gss_mechanism which someone is still using.\n");
 		return -1;
 	} else {
 		return 0;
@@ -244,7 +243,8 @@ gss_verify_mic(struct gss_ctx		*context_handle,
 u32
 gss_delete_sec_context(struct gss_ctx	**context_handle)
 {
-	dprintk("gss_delete_sec_context deleting %p\n",*context_handle);
+	dprintk("RPC:      gss_delete_sec_context deleting %p\n",
+			*context_handle);
 
 	if (!*context_handle)
 		return(GSS_S_NO_CONTEXT);

net/sunrpc/auth_gss/gss_pseudoflavors.c

@@ -82,7 +82,8 @@ gss_register_triple(u32 pseudoflavor, struct gss_api_mech *mech,
 
 	spin_lock(&registered_triples_lock);
 	if (do_lookup_triple_by_pseudoflavor(pseudoflavor)) {
-		printk("Registered pseudoflavor %d again\n", pseudoflavor);
+		printk(KERN_WARNING "RPC: Registered pseudoflavor %d again\n",
+				pseudoflavor);
 		goto err_unlock;
 	}
 	list_add(&triple->triples, &registered_triples);
@@ -145,7 +146,7 @@ gss_cmp_triples(u32 oid_len, char *oid_data, u32 qop, u32 service)
 	oid.len = oid_len;
 	oid.data = oid_data;
 
-	dprintk("RPC: gss_cmp_triples \n");
+	dprintk("RPC:      gss_cmp_triples\n");
 	print_sec_triple(&oid,qop,service);
 
 	spin_lock(&registered_triples_lock);
@@ -193,8 +194,8 @@ gss_pseudoflavor_to_service(u32 pseudoflavor)
 	triple = do_lookup_triple_by_pseudoflavor(pseudoflavor);
 	spin_unlock(&registered_triples_lock);
 	if (!triple) {
-		dprintk("RPC: gss_pseudoflavor_to_service called with"
-			" unsupported pseudoflavor %d\n", pseudoflavor);
+		dprintk("RPC:      gss_pseudoflavor_to_service called with unsupported pseudoflavor %d\n",
+				pseudoflavor);
 		return 0;
 	}
 	return triple->service;
@@ -211,8 +212,8 @@ gss_pseudoflavor_to_mech(u32 pseudoflavor) {
 	if (triple)
 		mech = gss_mech_get(triple->mech);
 	else
-		dprintk("RPC: gss_pseudoflavor_to_mech called with"
-			" unsupported pseudoflavor %d\n", pseudoflavor);
+		dprintk("RPC:      gss_pseudoflavor_to_mech called with unsupported pseudoflavor %d\n",
+				pseudoflavor);
 	return mech;
 }
 
@@ -223,8 +224,8 @@ gss_pseudoflavor_to_mechOID(u32 pseudoflavor, struct xdr_netobj * oid)
 
 	mech = gss_pseudoflavor_to_mech(pseudoflavor);
 	if (!mech)  {
-		dprintk("RPC: gss_pseudoflavor_to_mechOID called with"
-			" unsupported pseudoflavor %d\n", pseudoflavor);
+		dprintk("RPC:      gss_pseudoflavor_to_mechOID called with unsupported pseudoflavor %d\n",
+				pseudoflavor);
 		        return -1;
 	}
 	oid->len = mech->gm_oid.len;

net/sunrpc/auth_gss/svcauth_gss.c

@@ -570,14 +570,14 @@ gss_verify_header(struct svc_rqst *rqstp, struct rsc *rsci,
 	}
 
 	if (gc->gc_seq > MAXSEQ) {
-		dprintk("svcauth_gss: discarding request with large"
-			" sequence number %d\n", gc->gc_seq);
+		dprintk("RPC:      svcauth_gss: discarding request with large sequence number %d\n",
+				gc->gc_seq);
 		*authp = rpcsec_gsserr_ctxproblem;
 		return SVC_DENIED;
 	}
 	if (!gss_check_seq_num(rsci, gc->gc_seq)) {
-		dprintk("svcauth_gss: discarding request with old"
-				" sequence number %d\n", gc->gc_seq);
+		dprintk("RPC:      svcauth_gss: discarding request with old sequence number %d\n",
+				gc->gc_seq);
 		return SVC_DROP;
 	}
 	return SVC_OK;