SUNRPC: fix print format for tk_pid

The tk_pid field is an unsigned short.  The proper print format specifier for
that type is %5u, not %4d.

Also clean up some miscellaneous print formatting nits.
Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
Signed-off-by: Trond Myklebust <Trond.Myklebust@netapp.com>

net/sunrpc/auth.c

@@ -181,7 +181,7 @@ rpcauth_gc_credcache(struct rpc_auth *auth, struct hlist_head *free)
 	struct rpc_cred	*cred;
 	int		i;
 
-	dprintk("RPC: gc'ing RPC credentials for auth %p\n", auth);
+	dprintk("RPC:       gc'ing RPC credentials for auth %p\n", auth);
 	for (i = 0; i < RPC_CREDCACHE_NR; i++) {
 		hlist_for_each_safe(pos, next, &cache->hashtable[i]) {
 			cred = hlist_entry(pos, struct rpc_cred, cr_hash);
@@ -267,7 +267,7 @@ rpcauth_lookupcred(struct rpc_auth *auth, int flags)
 	};
 	struct rpc_cred *ret;
 
-	dprintk("RPC:     looking up %s cred\n",
+	dprintk("RPC:       looking up %s cred\n",
 		auth->au_ops->au_name);
 	get_group_info(acred.group_info);
 	ret = auth->au_ops->lookup_cred(auth, &acred, flags);
@@ -287,7 +287,7 @@ rpcauth_bindcred(struct rpc_task *task)
 	struct rpc_cred *ret;
 	int flags = 0;
 
-	dprintk("RPC: %4d looking up %s cred\n",
+	dprintk("RPC: %5u looking up %s cred\n",
 		task->tk_pid, task->tk_auth->au_ops->au_name);
 	get_group_info(acred.group_info);
 	if (task->tk_flags & RPC_TASK_ROOTCREDS)
@@ -304,8 +304,9 @@ rpcauth_bindcred(struct rpc_task *task)
 void
 rpcauth_holdcred(struct rpc_task *task)
 {
-	dprintk("RPC: %4d holding %s cred %p\n",
-		task->tk_pid, task->tk_auth->au_ops->au_name, task->tk_msg.rpc_cred);
+	dprintk("RPC: %5u holding %s cred %p\n",
+		task->tk_pid, task->tk_auth->au_ops->au_name,
+		task->tk_msg.rpc_cred);
 	if (task->tk_msg.rpc_cred)
 		get_rpccred(task->tk_msg.rpc_cred);
 }
@@ -324,7 +325,7 @@ rpcauth_unbindcred(struct rpc_task *task)
 {
 	struct rpc_cred	*cred = task->tk_msg.rpc_cred;
 
-	dprintk("RPC: %4d releasing %s cred %p\n",
+	dprintk("RPC: %5u releasing %s cred %p\n",
 		task->tk_pid, task->tk_auth->au_ops->au_name, cred);
 
 	put_rpccred(cred);
@@ -336,7 +337,7 @@ rpcauth_marshcred(struct rpc_task *task, __be32 *p)
 {
 	struct rpc_cred	*cred = task->tk_msg.rpc_cred;
 
-	dprintk("RPC: %4d marshaling %s cred %p\n",
+	dprintk("RPC: %5u marshaling %s cred %p\n",
 		task->tk_pid, task->tk_auth->au_ops->au_name, cred);
 
 	return cred->cr_ops->crmarshal(task, p);
@@ -347,7 +348,7 @@ rpcauth_checkverf(struct rpc_task *task, __be32 *p)
 {
 	struct rpc_cred	*cred = task->tk_msg.rpc_cred;
 
-	dprintk("RPC: %4d validating %s cred %p\n",
+	dprintk("RPC: %5u validating %s cred %p\n",
 		task->tk_pid, task->tk_auth->au_ops->au_name, cred);
 
 	return cred->cr_ops->crvalidate(task, p);
@@ -359,7 +360,7 @@ rpcauth_wrap_req(struct rpc_task *task, kxdrproc_t encode, void *rqstp,
 {
 	struct rpc_cred *cred = task->tk_msg.rpc_cred;
 
-	dprintk("RPC: %4d using %s cred %p to wrap rpc data\n",
+	dprintk("RPC: %5u using %s cred %p to wrap rpc data\n",
 			task->tk_pid, cred->cr_ops->cr_name, cred);
 	if (cred->cr_ops->crwrap_req)
 		return cred->cr_ops->crwrap_req(task, encode, rqstp, data, obj);
@@ -373,7 +374,7 @@ rpcauth_unwrap_resp(struct rpc_task *task, kxdrproc_t decode, void *rqstp,
 {
 	struct rpc_cred *cred = task->tk_msg.rpc_cred;
 
-	dprintk("RPC: %4d using %s cred %p to unwrap rpc data\n",
+	dprintk("RPC: %5u using %s cred %p to unwrap rpc data\n",
 			task->tk_pid, cred->cr_ops->cr_name, cred);
 	if (cred->cr_ops->crunwrap_resp)
 		return cred->cr_ops->crunwrap_resp(task, decode, rqstp,
@@ -388,7 +389,7 @@ rpcauth_refreshcred(struct rpc_task *task)
 	struct rpc_cred	*cred = task->tk_msg.rpc_cred;
 	int err;
 
-	dprintk("RPC: %4d refreshing %s cred %p\n",
+	dprintk("RPC: %5u refreshing %s cred %p\n",
 		task->tk_pid, task->tk_auth->au_ops->au_name, cred);
 
 	err = cred->cr_ops->crrefresh(task);
@@ -400,7 +401,7 @@ rpcauth_refreshcred(struct rpc_task *task)
 void
 rpcauth_invalcred(struct rpc_task *task)
 {
-	dprintk("RPC: %4d invalidating %s cred %p\n",
+	dprintk("RPC: %5u invalidating %s cred %p\n",
 		task->tk_pid, task->tk_auth->au_ops->au_name, task->tk_msg.rpc_cred);
 	spin_lock(&rpc_credcache_lock);
 	if (task->tk_msg.rpc_cred)

net/sunrpc/auth_unix.c

@@ -39,7 +39,8 @@ static struct rpc_credops	unix_credops;
 static struct rpc_auth *
 unx_create(struct rpc_clnt *clnt, rpc_authflavor_t flavor)
 {
-	dprintk("RPC: creating UNIX authenticator for client %p\n", clnt);
+	dprintk("RPC:       creating UNIX authenticator for client %p\n",
+			clnt);
 	if (atomic_inc_return(&unix_auth.au_count) == 0)
 		unix_cred_cache.nextgc = jiffies + (unix_cred_cache.expire >> 1);
 	return &unix_auth;
@@ -48,7 +49,7 @@ unx_create(struct rpc_clnt *clnt, rpc_authflavor_t flavor)
 static void
 unx_destroy(struct rpc_auth *auth)
 {
-	dprintk("RPC: destroying UNIX authenticator %p\n", auth);
+	dprintk("RPC:       destroying UNIX authenticator %p\n", auth);
 	rpcauth_free_credcache(auth);
 }
 
@@ -67,8 +68,8 @@ unx_create_cred(struct rpc_auth *auth, struct auth_cred *acred, int flags)
 	struct unx_cred	*cred;
 	int		i;
 
-	dprintk("RPC:      allocating UNIX cred for uid %d gid %d\n",
-				acred->uid, acred->gid);
+	dprintk("RPC:       allocating UNIX cred for uid %d gid %d\n",
+			acred->uid, acred->gid);
 
 	if (!(cred = kmalloc(sizeof(*cred), GFP_KERNEL)))
 		return ERR_PTR(-ENOMEM);

net/sunrpc/cache.c

@@ -215,7 +215,8 @@ int cache_check(struct cache_detail *detail,
 		if (rv == -EAGAIN)
 			rv = -ENOENT;
 	} else if (rv == -EAGAIN || age > refresh_age/2) {
-		dprintk("Want update, refage=%ld, age=%ld\n", refresh_age, age);
+		dprintk("RPC:       Want update, refage=%ld, age=%ld\n",
+				refresh_age, age);
 		if (!test_and_set_bit(CACHE_PENDING, &h->flags)) {
 			switch (cache_make_upcall(detail, h)) {
 			case -EINVAL:

net/sunrpc/pmap_clnt.c

@@ -97,7 +97,7 @@ void rpc_getport(struct rpc_task *task)
 	struct rpc_task *child;
 	int status;
 
-	dprintk("RPC: %4d rpc_getport(%s, %u, %u, %d)\n",
+	dprintk("RPC: %5u rpc_getport(%s, %u, %u, %d)\n",
 			task->tk_pid, clnt->cl_server,
 			clnt->cl_prog, clnt->cl_vers, xprt->prot);
 
@@ -178,7 +178,7 @@ int rpc_getport_external(struct sockaddr_in *sin, __u32 prog, __u32 vers, int pr
 	char		hostname[32];
 	int		status;
 
-	dprintk("RPC:      rpc_getport_external(%u.%u.%u.%u, %u, %u, %d)\n",
+	dprintk("RPC:       rpc_getport_external(%u.%u.%u.%u, %u, %u, %d)\n",
 			NIPQUAD(sin->sin_addr.s_addr), prog, vers, prot);
 
 	sprintf(hostname, "%u.%u.%u.%u", NIPQUAD(sin->sin_addr.s_addr));
@@ -221,7 +221,7 @@ static void pmap_getport_done(struct rpc_task *child, void *data)
 		status = 0;
 	}
 
-	dprintk("RPC: %4d pmap_getport_done(status %d, port %u)\n",
+	dprintk("RPC: %5u pmap_getport_done(status %d, port %u)\n",
 			child->tk_pid, status, map->pm_port);
 
 	pmap_wake_portmap_waiters(xprt, status);
@@ -257,13 +257,14 @@ int rpc_register(u32 prog, u32 vers, int prot, unsigned short port, int *okay)
 	struct rpc_clnt		*pmap_clnt;
 	int error = 0;
 
-	dprintk("RPC: registering (%u, %u, %d, %u) with portmapper.\n",
+	dprintk("RPC:       registering (%u, %u, %d, %u) with portmapper.\n",
 			prog, vers, prot, port);
 
 	pmap_clnt = pmap_create("localhost", &sin, IPPROTO_UDP, 1);
 	if (IS_ERR(pmap_clnt)) {
 		error = PTR_ERR(pmap_clnt);
-		dprintk("RPC: couldn't create pmap client. Error = %d\n", error);
+		dprintk("RPC:       couldn't create pmap client. Error = %d\n",
+				error);
 		return error;
 	}
 
@@ -274,7 +275,7 @@ int rpc_register(u32 prog, u32 vers, int prot, unsigned short port, int *okay)
 			"RPC: failed to contact portmap (errno %d).\n",
 			error);
 	}
-	dprintk("RPC: registration status %d/%d\n", error, *okay);
+	dprintk("RPC:       registration status %d/%d\n", error, *okay);
 
 	/* Client deleted automatically because cl_oneshot == 1 */
 	return error;
@@ -305,8 +306,9 @@ static struct rpc_clnt *pmap_create(char *hostname, struct sockaddr_in *srvaddr,
  */
 static int xdr_encode_mapping(struct rpc_rqst *req, __be32 *p, struct portmap_args *map)
 {
-	dprintk("RPC: xdr_encode_mapping(%u, %u, %u, %u)\n",
-		map->pm_prog, map->pm_vers, map->pm_prot, map->pm_port);
+	dprintk("RPC:       xdr_encode_mapping(%u, %u, %u, %u)\n",
+			map->pm_prog, map->pm_vers,
+			map->pm_prot, map->pm_port);
 	*p++ = htonl(map->pm_prog);
 	*p++ = htonl(map->pm_vers);
 	*p++ = htonl(map->pm_prot);

net/sunrpc/sched.c

@@ -74,7 +74,7 @@ static DEFINE_SPINLOCK(rpc_sched_lock);
 static inline void
 __rpc_disable_timer(struct rpc_task *task)
 {
-	dprintk("RPC: %4d disabling timer\n", task->tk_pid);
+	dprintk("RPC: %5u disabling timer\n", task->tk_pid);
 	task->tk_timeout_fn = NULL;
 	task->tk_timeout = 0;
 }
@@ -93,7 +93,7 @@ static void rpc_run_timer(struct rpc_task *task)
 	callback = task->tk_timeout_fn;
 	task->tk_timeout_fn = NULL;
 	if (callback && RPC_IS_QUEUED(task)) {
-		dprintk("RPC: %4d running timer\n", task->tk_pid);
+		dprintk("RPC: %5u running timer\n", task->tk_pid);
 		callback(task);
 	}
 	smp_mb__before_clear_bit();
@@ -110,7 +110,7 @@ __rpc_add_timer(struct rpc_task *task, rpc_action timer)
 	if (!task->tk_timeout)
 		return;
 
-	dprintk("RPC: %4d setting alarm for %lu ms\n",
+	dprintk("RPC: %5u setting alarm for %lu ms\n",
 			task->tk_pid, task->tk_timeout * 1000 / HZ);
 
 	if (timer)
@@ -132,7 +132,7 @@ rpc_delete_timer(struct rpc_task *task)
 		return;
 	if (test_and_clear_bit(RPC_TASK_HAS_TIMER, &task->tk_runstate)) {
 		del_singleshot_timer_sync(&task->tk_timer);
-		dprintk("RPC: %4d deleting timer\n", task->tk_pid);
+		dprintk("RPC: %5u deleting timer\n", task->tk_pid);
 	}
 }
 
@@ -179,8 +179,8 @@ static void __rpc_add_wait_queue(struct rpc_wait_queue *queue, struct rpc_task *
 	queue->qlen++;
 	rpc_set_queued(task);
 
-	dprintk("RPC: %4d added to queue %p \"%s\"\n",
-				task->tk_pid, queue, rpc_qname(queue));
+	dprintk("RPC: %5u added to queue %p \"%s\"\n",
+			task->tk_pid, queue, rpc_qname(queue));
 }
 
 /*
@@ -212,8 +212,8 @@ static void __rpc_remove_wait_queue(struct rpc_task *task)
 	else
 		list_del(&task->u.tk_wait.list);
 	queue->qlen--;
-	dprintk("RPC: %4d removed from queue %p \"%s\"\n",
-				task->tk_pid, queue, rpc_qname(queue));
+	dprintk("RPC: %5u removed from queue %p \"%s\"\n",
+			task->tk_pid, queue, rpc_qname(queue));
 }
 
 static inline void rpc_set_waitqueue_priority(struct rpc_wait_queue *queue, int priority)
@@ -344,8 +344,8 @@ static void rpc_make_runnable(struct rpc_task *task)
 static void __rpc_sleep_on(struct rpc_wait_queue *q, struct rpc_task *task,
 			rpc_action action, rpc_action timer)
 {
-	dprintk("RPC: %4d sleep_on(queue \"%s\" time %ld)\n", task->tk_pid,
-				rpc_qname(q), jiffies);
+	dprintk("RPC: %5u sleep_on(queue \"%s\" time %lu)\n",
+			task->tk_pid, rpc_qname(q), jiffies);
 
 	if (!RPC_IS_ASYNC(task) && !RPC_IS_ACTIVATED(task)) {
 		printk(KERN_ERR "RPC: Inactive synchronous task put to sleep!\n");
@@ -381,7 +381,8 @@ void rpc_sleep_on(struct rpc_wait_queue *q, struct rpc_task *task,
  */
 static void __rpc_do_wake_up_task(struct rpc_task *task)
 {
-	dprintk("RPC: %4d __rpc_wake_up_task (now %ld)\n", task->tk_pid, jiffies);
+	dprintk("RPC: %5u __rpc_wake_up_task (now %lu)\n",
+			task->tk_pid, jiffies);
 
 #ifdef RPC_DEBUG
 	BUG_ON(task->tk_magic != RPC_TASK_MAGIC_ID);
@@ -397,7 +398,7 @@ static void __rpc_do_wake_up_task(struct rpc_task *task)
 
 	rpc_make_runnable(task);
 
-	dprintk("RPC:      __rpc_wake_up_task done\n");
+	dprintk("RPC:       __rpc_wake_up_task done\n");
 }
 
 /*
@@ -418,7 +419,7 @@ static void __rpc_wake_up_task(struct rpc_task *task)
 static void
 __rpc_default_timer(struct rpc_task *task)
 {
-	dprintk("RPC: %d timeout (default timer)\n", task->tk_pid);
+	dprintk("RPC: %5u timeout (default timer)\n", task->tk_pid);
 	task->tk_status = -ETIMEDOUT;
 	rpc_wake_up_task(task);
 }
@@ -502,7 +503,8 @@ struct rpc_task * rpc_wake_up_next(struct rpc_wait_queue *queue)
 {
 	struct rpc_task	*task = NULL;
 
-	dprintk("RPC:      wake_up_next(%p \"%s\")\n", queue, rpc_qname(queue));
+	dprintk("RPC:       wake_up_next(%p \"%s\")\n",
+			queue, rpc_qname(queue));
 	rcu_read_lock_bh();
 	spin_lock(&queue->lock);
 	if (RPC_IS_PRIORITY(queue))
@@ -629,8 +631,8 @@ static void __rpc_execute(struct rpc_task *task)
 {
 	int		status = 0;
 
-	dprintk("RPC: %4d rpc_execute flgs %x\n",
-				task->tk_pid, task->tk_flags);
+	dprintk("RPC: %5u __rpc_execute flags=0x%x\n",
+			task->tk_pid, task->tk_flags);
 
 	BUG_ON(RPC_IS_QUEUED(task));
 
@@ -686,7 +688,7 @@ static void __rpc_execute(struct rpc_task *task)
 		}
 
 		/* sync task: sleep here */
-		dprintk("RPC: %4d sync task going to sleep\n", task->tk_pid);
+		dprintk("RPC: %5u sync task going to sleep\n", task->tk_pid);
 		/* Note: Caller should be using rpc_clnt_sigmask() */
 		status = out_of_line_wait_on_bit(&task->tk_runstate,
 				RPC_TASK_QUEUED, rpc_wait_bit_interruptible,
@@ -698,16 +700,17 @@ static void __rpc_execute(struct rpc_task *task)
 			 * clean up after sleeping on some queue, we don't
 			 * break the loop here, but go around once more.
 			 */
-			dprintk("RPC: %4d got signal\n", task->tk_pid);
+			dprintk("RPC: %5u got signal\n", task->tk_pid);
 			task->tk_flags |= RPC_TASK_KILLED;
 			rpc_exit(task, -ERESTARTSYS);
 			rpc_wake_up_task(task);
 		}
 		rpc_set_running(task);
-		dprintk("RPC: %4d sync task resuming\n", task->tk_pid);
+		dprintk("RPC: %5u sync task resuming\n", task->tk_pid);
 	}
 
-	dprintk("RPC: %4d, return %d, status %d\n", task->tk_pid, status, task->tk_status);
+	dprintk("RPC: %5u return %d, status %d\n", task->tk_pid, status,
+			task->tk_status);
 	/* Release all resources associated with the task */
 	rpc_release_task(task);
 }
@@ -824,7 +827,7 @@ void rpc_init_task(struct rpc_task *task, struct rpc_clnt *clnt, int flags, cons
 	/* starting timestamp */
 	task->tk_start = jiffies;
 
-	dprintk("RPC: %4d new task procpid %d\n", task->tk_pid,
+	dprintk("RPC:       new task initialized, procpid %u\n",
 				current->pid);
 }
 
@@ -837,7 +840,7 @@ rpc_alloc_task(void)
 static void rpc_free_task(struct rcu_head *rcu)
 {
 	struct rpc_task *task = container_of(rcu, struct rpc_task, u.tk_rcu);
-	dprintk("RPC: %4d freeing task\n", task->tk_pid);
+	dprintk("RPC: %5u freeing task\n", task->tk_pid);
 	mempool_free(task, rpc_task_mempool);
 }
 
@@ -856,7 +859,7 @@ struct rpc_task *rpc_new_task(struct rpc_clnt *clnt, int flags, const struct rpc
 
 	rpc_init_task(task, clnt, flags, tk_ops, calldata);
 
-	dprintk("RPC: %4d allocated task\n", task->tk_pid);
+	dprintk("RPC:       allocated task %p\n", task);
 	task->tk_flags |= RPC_TASK_DYNAMIC;
 out:
 	return task;
@@ -900,7 +903,7 @@ static void rpc_release_task(struct rpc_task *task)
 #ifdef RPC_DEBUG
 	BUG_ON(task->tk_magic != RPC_TASK_MAGIC_ID);
 #endif
-	dprintk("RPC: %4d release task\n", task->tk_pid);
+	dprintk("RPC: %5u release task\n", task->tk_pid);
 
 	/* Remove from global task list */
 	spin_lock(&rpc_sched_lock);
@@ -953,7 +956,7 @@ void rpc_killall_tasks(struct rpc_clnt *clnt)
 	struct rpc_task	*rovr;
 	struct list_head *le;
 
-	dprintk("RPC:      killing all tasks for client %p\n", clnt);
+	dprintk("RPC:       killing all tasks for client %p\n", clnt);
 
 	/*
 	 * Spin lock all_tasks to prevent changes...
@@ -982,7 +985,8 @@ static void rpciod_killall(void)
 		rpc_killall_tasks(NULL);
 		flush_workqueue(rpciod_workqueue);
 		if (!list_empty(&all_tasks)) {
-			dprintk("rpciod_killall: waiting for tasks to exit\n");
+			dprintk("RPC:       rpciod_killall: waiting for tasks "
+					"to exit\n");
 			yield();
 		}
 	}
@@ -1002,7 +1006,7 @@ rpciod_up(void)
 	int error = 0;
 
 	mutex_lock(&rpciod_mutex);
-	dprintk("rpciod_up: users %d\n", rpciod_users);
+	dprintk("RPC:       rpciod_up: users %u\n", rpciod_users);
 	rpciod_users++;
 	if (rpciod_workqueue)
 		goto out;
@@ -1010,7 +1014,7 @@ rpciod_up(void)
 	 * If there's no pid, we should be the first user.
 	 */
 	if (rpciod_users > 1)
-		printk(KERN_WARNING "rpciod_up: no workqueue, %d users??\n", rpciod_users);
+		printk(KERN_WARNING "rpciod_up: no workqueue, %u users??\n", rpciod_users);
 	/*
 	 * Create the rpciod thread and wait for it to start.
 	 */
@@ -1032,7 +1036,7 @@ void
 rpciod_down(void)
 {
 	mutex_lock(&rpciod_mutex);
-	dprintk("rpciod_down sema %d\n", rpciod_users);
+	dprintk("RPC:       rpciod_down sema %u\n", rpciod_users);
 	if (rpciod_users) {
 		if (--rpciod_users)
 			goto out;
@@ -1040,7 +1044,7 @@ rpciod_down(void)
 		printk(KERN_WARNING "rpciod_down: no users??\n");
 
 	if (!rpciod_workqueue) {
-		dprintk("rpciod_down: Nothing to do!\n");
+		dprintk("RPC:       rpciod_down: Nothing to do!\n");
 		goto out;
 	}
 	rpciod_killall();
@@ -1070,7 +1074,7 @@ void rpc_show_tasks(void)
 		if (RPC_IS_QUEUED(t))
 			rpc_waitq = rpc_qname(t->u.tk_wait.rpc_waitq);
 
-		printk("%05d %04d %04x %06d %8p %6d %8p %08ld %8s %8p %8p\n",
+		printk("%5u %04d %04x %6d %8p %6d %8p %8ld %8s %8p %8p\n",
 			t->tk_pid,
 			(t->tk_msg.rpc_proc ? t->tk_msg.rpc_proc->p_proc : -1),
 			t->tk_flags, t->tk_status,

net/sunrpc/stats.c

@@ -226,7 +226,7 @@ do_register(const char *name, void *data, const struct file_operations *fops)
 	struct proc_dir_entry *ent;
 
 	rpc_proc_init();
-	dprintk("RPC: registering /proc/net/rpc/%s\n", name);
+	dprintk("RPC:       registering /proc/net/rpc/%s\n", name);
 
 	ent = create_proc_entry(name, 0, proc_net_rpc);
 	if (ent) {
@@ -263,7 +263,7 @@ svc_proc_unregister(const char *name)
 void
 rpc_proc_init(void)
 {
-	dprintk("RPC: registering /proc/net/rpc\n");
+	dprintk("RPC:       registering /proc/net/rpc\n");
 	if (!proc_net_rpc) {
 		struct proc_dir_entry *ent;
 		ent = proc_mkdir("rpc", proc_net);
@@ -277,7 +277,7 @@ rpc_proc_init(void)
 void
 rpc_proc_exit(void)
 {
-	dprintk("RPC: unregistering /proc/net/rpc\n");
+	dprintk("RPC:       unregistering /proc/net/rpc\n");
 	if (proc_net_rpc) {
 		proc_net_rpc = NULL;
 		remove_proc_entry("net/rpc", NULL);

net/sunrpc/svc.c

@@ -317,7 +317,7 @@ __svc_create(struct svc_program *prog, unsigned int bufsize, int npools,
 	for (i = 0; i < serv->sv_nrpools; i++) {
 		struct svc_pool *pool = &serv->sv_pools[i];
 
-		dprintk("initialising pool %u for %s\n",
+		dprintk("svc: initialising pool %u for %s\n",
 				i, serv->sv_name);
 
 		pool->sp_id = i;
@@ -368,7 +368,7 @@ svc_destroy(struct svc_serv *serv)
 {
 	struct svc_sock	*svsk;
 
-	dprintk("RPC: svc_destroy(%s, %d)\n",
+	dprintk("svc: svc_destroy(%s, %d)\n",
 				serv->sv_program->pg_name,
 				serv->sv_nrthreads);
 
@@ -654,7 +654,7 @@ svc_register(struct svc_serv *serv, int proto, unsigned short port)
 			if (progp->pg_vers[i] == NULL)
 				continue;
 
-			dprintk("RPC: svc_register(%s, %s, %d, %d)%s\n",
+			dprintk("svc: svc_register(%s, %s, %d, %d)%s\n",
 					progp->pg_name,
 					proto == IPPROTO_UDP?  "udp" : "tcp",
 					port,

net/sunrpc/xprt.c

@@ -108,7 +108,7 @@ int xprt_reserve_xprt(struct rpc_task *task)
 	return 1;
 
 out_sleep:
-	dprintk("RPC: %4d failed to lock transport %p\n",
+	dprintk("RPC: %5u failed to lock transport %p\n",
 			task->tk_pid, xprt);
 	task->tk_timeout = 0;
 	task->tk_status = -EAGAIN;
@@ -158,7 +158,7 @@ int xprt_reserve_xprt_cong(struct rpc_task *task)
 	}
 	xprt_clear_locked(xprt);
 out_sleep:
-	dprintk("RPC: %4d failed to lock transport %p\n", task->tk_pid, xprt);
+	dprintk("RPC: %5u failed to lock transport %p\n", task->tk_pid, xprt);
 	task->tk_timeout = 0;
 	task->tk_status = -EAGAIN;
 	if (req && req->rq_ntrans)
@@ -281,7 +281,7 @@ __xprt_get_cong(struct rpc_xprt *xprt, struct rpc_task *task)
 
 	if (req->rq_cong)
 		return 1;
-	dprintk("RPC: %4d xprt_cwnd_limited cong = %ld cwnd = %ld\n",
+	dprintk("RPC: %5u xprt_cwnd_limited cong = %lu cwnd = %lu\n",
 			task->tk_pid, xprt->cong, xprt->cwnd);
 	if (RPCXPRT_CONGESTED(xprt))
 		return 0;
@@ -340,7 +340,7 @@ void xprt_adjust_cwnd(struct rpc_task *task, int result)
 		if (cwnd < RPC_CWNDSCALE)
 			cwnd = RPC_CWNDSCALE;
 	}
-	dprintk("RPC:      cong %ld, cwnd was %ld, now %ld\n",
+	dprintk("RPC:       cong %ld, cwnd was %ld, now %ld\n",
 			xprt->cong, xprt->cwnd, cwnd);
 	xprt->cwnd = cwnd;
 	__xprt_put_cong(xprt, req);
@@ -387,8 +387,8 @@ void xprt_write_space(struct rpc_xprt *xprt)
 
 	spin_lock_bh(&xprt->transport_lock);
 	if (xprt->snd_task) {
-		dprintk("RPC:      write space: waking waiting task on xprt %p\n",
-				xprt);
+		dprintk("RPC:       write space: waking waiting task on "
+				"xprt %p\n", xprt);
 		rpc_wake_up_task(xprt->snd_task);
 	}
 	spin_unlock_bh(&xprt->transport_lock);
@@ -494,7 +494,7 @@ static void xprt_autoclose(struct work_struct *work)
  */
 void xprt_disconnect(struct rpc_xprt *xprt)
 {
-	dprintk("RPC:      disconnected transport %p\n", xprt);
+	dprintk("RPC:       disconnected transport %p\n", xprt);
 	spin_lock_bh(&xprt->transport_lock);
 	xprt_clear_connected(xprt);
 	xprt_wake_pending_tasks(xprt, -ENOTCONN);
@@ -530,7 +530,7 @@ void xprt_connect(struct rpc_task *task)
 {
 	struct rpc_xprt	*xprt = task->tk_xprt;
 
-	dprintk("RPC: %4d xprt_connect xprt %p %s connected\n", task->tk_pid,
+	dprintk("RPC: %5u xprt_connect xprt %p %s connected\n", task->tk_pid,
 			xprt, (xprt_connected(xprt) ? "is" : "is not"));
 
 	if (!xprt_bound(xprt)) {
@@ -560,7 +560,7 @@ static void xprt_connect_status(struct rpc_task *task)
 	if (task->tk_status >= 0) {
 		xprt->stat.connect_count++;
 		xprt->stat.connect_time += (long)jiffies - xprt->stat.connect_start;
-		dprintk("RPC: %4d xprt_connect_status: connection established\n",
+		dprintk("RPC: %5u xprt_connect_status: connection established\n",
 				task->tk_pid);
 		return;
 	}
@@ -568,20 +568,22 @@ static void xprt_connect_status(struct rpc_task *task)
 	switch (task->tk_status) {
 	case -ECONNREFUSED:
 	case -ECONNRESET:
-		dprintk("RPC: %4d xprt_connect_status: server %s refused connection\n",
-				task->tk_pid, task->tk_client->cl_server);
+		dprintk("RPC: %5u xprt_connect_status: server %s refused "
+				"connection\n", task->tk_pid,
+				task->tk_client->cl_server);
 		break;
 	case -ENOTCONN:
-		dprintk("RPC: %4d xprt_connect_status: connection broken\n",
+		dprintk("RPC: %5u xprt_connect_status: connection broken\n",
 				task->tk_pid);
 		break;
 	case -ETIMEDOUT:
-		dprintk("RPC: %4d xprt_connect_status: connect attempt timed out\n",
-				task->tk_pid);
+		dprintk("RPC: %5u xprt_connect_status: connect attempt timed "
+				"out\n", task->tk_pid);
 		break;
 	default:
-		dprintk("RPC: %4d xprt_connect_status: error %d connecting to server %s\n",
-				task->tk_pid, -task->tk_status, task->tk_client->cl_server);
+		dprintk("RPC: %5u xprt_connect_status: error %d connecting to "
+				"server %s\n", task->tk_pid, -task->tk_status,
+				task->tk_client->cl_server);
 		xprt_release_write(xprt, task);
 		task->tk_status = -EIO;
 	}
@@ -602,6 +604,9 @@ struct rpc_rqst *xprt_lookup_rqst(struct rpc_xprt *xprt, __be32 xid)
 		if (entry->rq_xid == xid)
 			return entry;
 	}
+
+	dprintk("RPC:       xprt_lookup_rqst did not find xid %08x\n",
+			ntohl(xid));
 	xprt->stat.bad_xids++;
 	return NULL;
 }
@@ -654,7 +659,7 @@ static void xprt_timer(struct rpc_task *task)
 	struct rpc_rqst *req = task->tk_rqstp;
 	struct rpc_xprt *xprt = req->rq_xprt;
 
-	dprintk("RPC: %4d xprt_timer\n", task->tk_pid);
+	dprintk("RPC: %5u xprt_timer\n", task->tk_pid);
 
 	spin_lock(&xprt->transport_lock);
 	if (!req->rq_received) {
@@ -678,7 +683,7 @@ int xprt_prepare_transmit(struct rpc_task *task)
 	struct rpc_xprt	*xprt = req->rq_xprt;
 	int err = 0;
 
-	dprintk("RPC: %4d xprt_prepare_transmit\n", task->tk_pid);
+	dprintk("RPC: %5u xprt_prepare_transmit\n", task->tk_pid);
 
 	spin_lock_bh(&xprt->transport_lock);
 	if (req->rq_received && !req->rq_bytes_sent) {
@@ -716,7 +721,7 @@ void xprt_transmit(struct rpc_task *task)
 	struct rpc_xprt	*xprt = req->rq_xprt;
 	int status;
 
-	dprintk("RPC: %4d xprt_transmit(%u)\n", task->tk_pid, req->rq_slen);
+	dprintk("RPC: %5u xprt_transmit(%u)\n", task->tk_pid, req->rq_slen);
 
 	if (!req->rq_received) {
 		if (list_empty(&req->rq_list)) {
@@ -736,7 +741,7 @@ void xprt_transmit(struct rpc_task *task)
 
 	status = xprt->ops->send_request(task);
 	if (status == 0) {
-		dprintk("RPC: %4d xmit complete\n", task->tk_pid);
+		dprintk("RPC: %5u xmit complete\n", task->tk_pid);
 		spin_lock_bh(&xprt->transport_lock);
 
 		xprt->ops->set_retrans_timeout(task);
@@ -777,7 +782,7 @@ static inline void do_xprt_reserve(struct rpc_task *task)
 		xprt_request_init(task, xprt);
 		return;
 	}
-	dprintk("RPC:      waiting for request slot\n");
+	dprintk("RPC:       waiting for request slot\n");
 	task->tk_status = -EAGAIN;
 	task->tk_timeout = 0;
 	rpc_sleep_on(&xprt->backlog, task, NULL, NULL);
@@ -822,7 +827,7 @@ static void xprt_request_init(struct rpc_task *task, struct rpc_xprt *xprt)
 	req->rq_xid     = xprt_alloc_xid(xprt);
 	req->rq_release_snd_buf = NULL;
 	xprt_reset_majortimeo(req);
-	dprintk("RPC: %4d reserved req %p xid %08x\n", task->tk_pid,
+	dprintk("RPC: %5u reserved req %p xid %08x\n", task->tk_pid,
 			req, ntohl(req->rq_xid));
 }
 
@@ -856,7 +861,7 @@ void xprt_release(struct rpc_task *task)
 		req->rq_release_snd_buf(req);
 	memset(req, 0, sizeof(*req));	/* mark unused */
 
-	dprintk("RPC: %4d release request %p\n", task->tk_pid, req);
+	dprintk("RPC: %5u release request %p\n", task->tk_pid, req);
 
 	spin_lock(&xprt->reserve_lock);
 	list_add(&req->rq_list, &xprt->free);
@@ -906,7 +911,7 @@ struct rpc_xprt *xprt_create_transport(int proto, struct sockaddr *ap, size_t si
 		return ERR_PTR(-EIO);
 	}
 	if (IS_ERR(xprt)) {
-		dprintk("RPC:      xprt_create_transport: failed, %ld\n",
+		dprintk("RPC:       xprt_create_transport: failed, %ld\n",
 				-PTR_ERR(xprt));
 		return xprt;
 	}
@@ -936,7 +941,7 @@ struct rpc_xprt *xprt_create_transport(int proto, struct sockaddr *ap, size_t si
 
 	xprt_init_xid(xprt);
 
-	dprintk("RPC:      created transport %p with %u slots\n", xprt,
+	dprintk("RPC:       created transport %p with %u slots\n", xprt,
 			xprt->max_reqs);
 
 	return xprt;
@@ -951,7 +956,7 @@ static void xprt_destroy(struct kref *kref)
 {
 	struct rpc_xprt *xprt = container_of(kref, struct rpc_xprt, kref);
 
-	dprintk("RPC:      destroying transport %p\n", xprt);
+	dprintk("RPC:       destroying transport %p\n", xprt);
 	xprt->shutdown = 1;
 	del_timer_sync(&xprt->timer);