[PATCH v1 00/14] Some RPC server dprintk clean up

[PATCH v1 00/14] Some RPC server dprintk clean up

[Chuck Lever]

Hi Bruce-

Here are some random scribblings I did over the past week to start
cleaning up dprintk call sites in the kernel RPC server
implementation.

As I stated before, it's my opinion (and not at all a NACK) that
because we've never left single dprintk call sites in place for
deprecated DEBUG failicities, we don't need to do it here. My
preference is simply to deal with this in rpcdebug if we think there
is a strong need. I'd rather see a warning note come out of the
administrative interface immediately upon attempted use, instead of
to see nothing and then see a kernel warning at some point much
later (or not at all if the only remaining call site for that
facility is never encountered).

I know others have different opinions about this. We had only a few
minutes to discuss it during the BAT, and the issue might still be
without consensus. There's still opportunity to work it out on list.

---

Chuck Lever (14):
      SUNRPC: Update the show_svc_xprt_flags() macro
      SUNRPC: Remove dprintk call sites from svcauth_unix.c
      SUNRPC: Remove dprintk call site from svc_authenticate()
      SUNRPC: Clean up svc_destroy()
      SUNRPC: Remove dprintk call site from __svc_create()
      SUNRPC: Remove dprintk call site from bc_svc_process()
      SUNRPC: Remove redundant dprintk call sites from svc_process_common()
      SUNRPC: Report short RPC messages via a tracepoint
      SUNRPC: Report RPC messages with unknown programs via a tracepoint
      SUNRPC: Report RPC messages with unknown versions via a tracepoint
      SUNRPC: Report RPC messages with unknown procedures via a tracepoint
      SUNRPC: Report RPC messages that can't be decoded via a tracepoint
      SUNRPC: Fix kdoc comment for svc_unregister()
      SUNRPC: Yank some low-value dprintk call sites


 include/trace/events/sunrpc.h | 156 ++++++++++++++++++++++++++++++----
 net/sunrpc/svc.c              |  78 ++++-------------
 net/sunrpc/svc_xprt.c         |  19 -----
 net/sunrpc/svcauth.c          |   4 -
 net/sunrpc/svcauth_unix.c     |   4 -
 5 files changed, 155 insertions(+), 106 deletions(-)

--
Chuck Lever

[PATCH v1 01/14] SUNRPC: Update the show_svc_xprt_flags() macro

[Chuck Lever]

Use BIT() instead of open-coding the bit shift. Also, compact the
information that is displayed in the log by removing the redundant
"XPT_" string from each symbolic name.

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 include/trace/events/sunrpc.h |   32 ++++++++++++++++----------------
 1 file changed, 16 insertions(+), 16 deletions(-)

diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h
index 9ea59959a2fe..23b0964e0425 100644
--- a/include/trace/events/sunrpc.h
+++ b/include/trace/events/sunrpc.h
@@ -1705,22 +1705,22 @@ DEFINE_EVENT(svc_rqst_status, svc_send,
 	TP_PROTO(struct svc_rqst *rqst, int status),
 	TP_ARGS(rqst, status));
 
-#define show_svc_xprt_flags(flags)					\
-	__print_flags(flags, "|",					\
-		{ (1UL << XPT_BUSY),		"XPT_BUSY"},		\
-		{ (1UL << XPT_CONN),		"XPT_CONN"},		\
-		{ (1UL << XPT_CLOSE),		"XPT_CLOSE"},		\
-		{ (1UL << XPT_DATA),		"XPT_DATA"},		\
-		{ (1UL << XPT_TEMP),		"XPT_TEMP"},		\
-		{ (1UL << XPT_DEAD),		"XPT_DEAD"},		\
-		{ (1UL << XPT_CHNGBUF),		"XPT_CHNGBUF"},		\
-		{ (1UL << XPT_DEFERRED),	"XPT_DEFERRED"},	\
-		{ (1UL << XPT_OLD),		"XPT_OLD"},		\
-		{ (1UL << XPT_LISTENER),	"XPT_LISTENER"},	\
-		{ (1UL << XPT_CACHE_AUTH),	"XPT_CACHE_AUTH"},	\
-		{ (1UL << XPT_LOCAL),		"XPT_LOCAL"},		\
-		{ (1UL << XPT_KILL_TEMP),	"XPT_KILL_TEMP"},	\
-		{ (1UL << XPT_CONG_CTRL),	"XPT_CONG_CTRL"})
+#define show_svc_xprt_flags(flags)				\
+	__print_flags(flags, "|",				\
+		{ BIT(XPT_BUSY),	"BUSY" },		\
+		{ BIT(XPT_CONN),	"CONN" },		\
+		{ BIT(XPT_CLOSE),	"CLOSE" },		\
+		{ BIT(XPT_DATA),	"DATA" },		\
+		{ BIT(XPT_TEMP),	"TEMP" },		\
+		{ BIT(XPT_DEAD),	"DEAD" },		\
+		{ BIT(XPT_CHNGBUF),	"CHNGBUF" },		\
+		{ BIT(XPT_DEFERRED),	"DEFERRED" },		\
+		{ BIT(XPT_OLD),		"OLD" },		\
+		{ BIT(XPT_LISTENER),	"LISTENER" },		\
+		{ BIT(XPT_CACHE_AUTH),	"CACHE_AUTH" },		\
+		{ BIT(XPT_LOCAL),	"LOCAL" },		\
+		{ BIT(XPT_KILL_TEMP),	"KILL_TEMP" },		\
+		{ BIT(XPT_CONG_CTRL),	"CONG_CTRL" })
 
 TRACE_EVENT(svc_xprt_create_err,
 	TP_PROTO(

[PATCH v1 02/14] SUNRPC: Remove dprintk call sites from svcauth_unix.c

[Chuck Lever]

Deprecation. Remove low-value dprintk call sites.

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 net/sunrpc/svcauth_unix.c |    4 ----
 1 file changed, 4 deletions(-)

diff --git a/net/sunrpc/svcauth_unix.c b/net/sunrpc/svcauth_unix.c
index d7ed7d49115a..225845035e0e 100644
--- a/net/sunrpc/svcauth_unix.c
+++ b/net/sunrpc/svcauth_unix.c
@@ -17,8 +17,6 @@
 #include <net/ipv6.h>
 #include <linux/kernel.h>
 #include <linux/user_namespace.h>
-#define RPCDBG_FACILITY	RPCDBG_AUTH
-
 
 #include "netns.h"
 
@@ -739,12 +737,10 @@ svcauth_null_accept(struct svc_rqst *rqstp)
 		return SVC_GARBAGE;
 
 	if (svc_getu32(argv) != 0) {
-		dprintk("svc: bad null cred\n");
 		rqstp->rq_auth_stat = rpc_autherr_badcred;
 		return SVC_DENIED;
 	}
 	if (svc_getu32(argv) != htonl(RPC_AUTH_NULL) || svc_getu32(argv) != 0) {
-		dprintk("svc: bad null verf\n");
 		rqstp->rq_auth_stat = rpc_autherr_badverf;
 		return SVC_DENIED;
 	}

[PATCH v1 03/14] SUNRPC: Remove dprintk call site from svc_authenticate()

[Chuck Lever]

Deprecation. This dprintk call site has been replaced by the
svc_authenticate tracepoint invoked in svc_process_common().

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 net/sunrpc/svcauth.c |    4 ----
 1 file changed, 4 deletions(-)

diff --git a/net/sunrpc/svcauth.c b/net/sunrpc/svcauth.c
index 5a8b8e03fdd4..829eb8920ea3 100644
--- a/net/sunrpc/svcauth.c
+++ b/net/sunrpc/svcauth.c
@@ -23,8 +23,6 @@
 
 #include "sunrpc.h"
 
-#define RPCDBG_FACILITY	RPCDBG_AUTH
-
 
 /*
  * Table of authenticators
@@ -68,8 +66,6 @@ svc_authenticate(struct svc_rqst *rqstp)
 
 	flavor = svc_getnl(&rqstp->rq_arg.head[0]);
 
-	dprintk("svc: svc_authenticate (%d)\n", flavor);
-
 	aops = svc_get_auth_ops(flavor);
 	if (aops == NULL) {
 		rqstp->rq_auth_stat = rpc_autherr_badcred;

[PATCH v1 04/14] SUNRPC: Clean up svc_destroy()

[Chuck Lever]

Clean up. Remove rarely-used printk() call sites in svc_destroy, and
defang the BUG_ON sites.

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 net/sunrpc/svc.c |   23 ++++++++++-------------
 1 file changed, 10 insertions(+), 13 deletions(-)

diff --git a/net/sunrpc/svc.c b/net/sunrpc/svc.c
index 4292278a9552..f7d8401d97ac 100644
--- a/net/sunrpc/svc.c
+++ b/net/sunrpc/svc.c
@@ -521,24 +521,21 @@ void svc_shutdown_net(struct svc_serv *serv, struct net *net)
 }
 EXPORT_SYMBOL_GPL(svc_shutdown_net);
 
-/*
- * Destroy an RPC service. Should be called with appropriate locking to
- * protect the sv_nrthreads, sv_permsocks and sv_tempsocks.
+/**
+ * svc_destroy - Destroy an RPC service
+ * @serv: RPC server context to be destroyed
+ *
+ * Caller must serialize to protect sv_nrthreads, sv_permsocks
+ * and sv_tempsocks.
  */
-void
-svc_destroy(struct svc_serv *serv)
+void svc_destroy(struct svc_serv *serv)
 {
-	dprintk("svc: svc_destroy(%s, %d)\n",
-				serv->sv_program->pg_name,
-				serv->sv_nrthreads);
-
 	if (serv->sv_nrthreads) {
 		if (--(serv->sv_nrthreads) != 0) {
 			svc_sock_update_bufs(serv);
 			return;
 		}
-	} else
-		printk("svc_destroy: no threads for serv=%p!\n", serv);
+	}
 
 	del_timer_sync(&serv->sv_temptimer);
 
@@ -546,8 +543,8 @@ svc_destroy(struct svc_serv *serv)
 	 * The last user is gone and thus all sockets have to be destroyed to
 	 * the point. Check this.
 	 */
-	BUG_ON(!list_empty(&serv->sv_permsocks));
-	BUG_ON(!list_empty(&serv->sv_tempsocks));
+	WARN_ON(!list_empty(&serv->sv_permsocks));
+	WARN_ON(!list_empty(&serv->sv_tempsocks));
 
 	cache_clean_deferred(serv);
 

[PATCH v1 05/14] SUNRPC: Remove dprintk call site from __svc_create()

[Chuck Lever]

Deprecation. This appears to be a low-value dprintk.

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 net/sunrpc/svc.c |    3 ---
 1 file changed, 3 deletions(-)

diff --git a/net/sunrpc/svc.c b/net/sunrpc/svc.c
index f7d8401d97ac..8ca60bfaa073 100644
--- a/net/sunrpc/svc.c
+++ b/net/sunrpc/svc.c
@@ -475,9 +475,6 @@ __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("svc: initialising pool %u for %s\n",
-				i, serv->sv_name);
-
 		pool->sp_id = i;
 		INIT_LIST_HEAD(&pool->sp_sockets);
 		INIT_LIST_HEAD(&pool->sp_all_threads);

[PATCH v1 06/14] SUNRPC: Remove dprintk call site from bc_svc_process()

[Chuck Lever]

Deprecation. Enabling tracepoints in the RPC client gives similar
observability.

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 net/sunrpc/svc.c |    4 ----
 1 file changed, 4 deletions(-)

diff --git a/net/sunrpc/svc.c b/net/sunrpc/svc.c
index 8ca60bfaa073..dbc44178daac 100644
--- a/net/sunrpc/svc.c
+++ b/net/sunrpc/svc.c
@@ -1472,7 +1472,6 @@ svc_process(struct svc_rqst *rqstp)
 	dir  = svc_getnl(argv);
 	if (dir != 0) {
 		/* direction != CALL */
-		svc_printk(rqstp, "bad direction %d, dropping request\n", dir);
 		serv->sv_stats->rpcbadfmt++;
 		goto out_drop;
 	}
@@ -1502,8 +1501,6 @@ bc_svc_process(struct svc_serv *serv, struct rpc_rqst *req,
 	int proc_error;
 	int error;
 
-	dprintk("svc: %s(%p)\n", __func__, req);
-
 	/* Build the svc_rqst used by the common processing routine */
 	rqstp->rq_xid = req->rq_xid;
 	rqstp->rq_prot = req->rq_xprt->prot;
@@ -1561,7 +1558,6 @@ bc_svc_process(struct svc_serv *serv, struct rpc_rqst *req,
 	rpc_put_task(task);
 
 out:
-	dprintk("svc: %s(), error=%d\n", __func__, error);
 	return error;
 }
 EXPORT_SYMBOL_GPL(bc_svc_process);

[PATCH v1 07/14] SUNRPC: Remove redundant dprintk call sites from svc_process_common()

[Chuck Lever]

Deprecation. There are already tracepoints that cover these cases.

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 net/sunrpc/svc.c |    4 ----
 1 file changed, 4 deletions(-)

diff --git a/net/sunrpc/svc.c b/net/sunrpc/svc.c
index dbc44178daac..5cfbda94e759 100644
--- a/net/sunrpc/svc.c
+++ b/net/sunrpc/svc.c
@@ -1369,7 +1369,6 @@ svc_process_common(struct svc_rqst *rqstp, struct kvec *argv, struct kvec *resv)
 
  dropit:
 	svc_authorise(rqstp);	/* doesn't hurt to call this twice */
-	dprintk("svc: svc_process dropit\n");
 	return 0;
 
  close:
@@ -1377,7 +1376,6 @@ svc_process_common(struct svc_rqst *rqstp, struct kvec *argv, struct kvec *resv)
 close_xprt:
 	if (rqstp->rq_xprt && test_bit(XPT_TEMP, &rqstp->rq_xprt->xpt_flags))
 		svc_close_xprt(rqstp->rq_xprt);
-	dprintk("svc: svc_process close\n");
 	return 0;
 
 err_short_len:
@@ -1394,8 +1392,6 @@ svc_process_common(struct svc_rqst *rqstp, struct kvec *argv, struct kvec *resv)
 	goto sendit;
 
 err_bad_auth:
-	dprintk("svc: authentication failed (%d)\n",
-		be32_to_cpu(rqstp->rq_auth_stat));
 	serv->sv_stats->rpcbadauth++;
 	/* Restore write pointer to location of accept status: */
 	xdr_ressize_check(rqstp, reply_statp);

[PATCH v1 08/14] SUNRPC: Report short RPC messages via a tracepoint

[Chuck Lever]

Replace a dprintk call site. The new tracepoint can be left enabled
persistently to capture problems.

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 include/trace/events/sunrpc.h |   23 +++++++++++++++++++++++
 net/sunrpc/svc.c              |    3 +--
 2 files changed, 24 insertions(+), 2 deletions(-)

diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h
index 23b0964e0425..3cfdd0ef6600 100644
--- a/include/trace/events/sunrpc.h
+++ b/include/trace/events/sunrpc.h
@@ -1642,6 +1642,29 @@ TRACE_EVENT(svc_process,
 	)
 );
 
+TRACE_EVENT(svc_decode_len_err,
+	TP_PROTO(
+		const struct svc_rqst *rqst,
+		const struct kvec *argv
+	),
+
+	TP_ARGS(rqst, argv),
+
+	TP_STRUCT__entry(
+		__field(size_t, len)
+		__string(addr, rqst->rq_xprt ?
+			 rqst->rq_xprt->xpt_remotebuf : "(null)")
+	),
+
+	TP_fast_assign(
+		__entry->len = argv->iov_len;
+		__assign_str(addr, rqst->rq_xprt ?
+			     rqst->rq_xprt->xpt_remotebuf : "(null)");
+	),
+
+	TP_printk("addr=%s len=%zu", __get_str(addr), __entry->len)
+);
+
 DECLARE_EVENT_CLASS(svc_rqst_event,
 
 	TP_PROTO(
diff --git a/net/sunrpc/svc.c b/net/sunrpc/svc.c
index 5cfbda94e759..3d95faffe43b 100644
--- a/net/sunrpc/svc.c
+++ b/net/sunrpc/svc.c
@@ -1379,8 +1379,7 @@ svc_process_common(struct svc_rqst *rqstp, struct kvec *argv, struct kvec *resv)
 	return 0;
 
 err_short_len:
-	svc_printk(rqstp, "short len %zd, dropping request\n",
-			argv->iov_len);
+	trace_svc_decode_len_err(rqstp, argv);
 	goto close_xprt;
 
 err_bad_rpc:

[PATCH v1 09/14] SUNRPC: Report RPC messages with unknown programs via a tracepoint

[Chuck Lever]

Replace a dprintk call site. The new tracepoint can be left enabled
persistently to capture problems.

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 include/trace/events/sunrpc.h |   23 +++++++++++++++++++++++
 net/sunrpc/svc.c              |    2 +-
 2 files changed, 24 insertions(+), 1 deletion(-)

diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h
index 3cfdd0ef6600..db581a837f1b 100644
--- a/include/trace/events/sunrpc.h
+++ b/include/trace/events/sunrpc.h
@@ -1665,6 +1665,29 @@ TRACE_EVENT(svc_decode_len_err,
 	TP_printk("addr=%s len=%zu", __get_str(addr), __entry->len)
 );
 
+TRACE_EVENT(svc_decode_prog_unavail_err,
+	TP_PROTO(
+		const struct svc_rqst *rqst,
+		u32 program
+	),
+
+	TP_ARGS(rqst, program),
+
+	TP_STRUCT__entry(
+		__field(u32, program)
+		__string(addr, rqst->rq_xprt ?
+			 rqst->rq_xprt->xpt_remotebuf : "(null)")
+	),
+
+	TP_fast_assign(
+		__entry->program = program;
+		__assign_str(addr, rqst->rq_xprt ?
+			     rqst->rq_xprt->xpt_remotebuf : "(null)");
+	),
+
+	TP_printk("addr=%s program=%u", __get_str(addr), __entry->program)
+);
+
 DECLARE_EVENT_CLASS(svc_rqst_event,
 
 	TP_PROTO(
diff --git a/net/sunrpc/svc.c b/net/sunrpc/svc.c
index 3d95faffe43b..a057d1373579 100644
--- a/net/sunrpc/svc.c
+++ b/net/sunrpc/svc.c
@@ -1400,7 +1400,7 @@ svc_process_common(struct svc_rqst *rqstp, struct kvec *argv, struct kvec *resv)
 	goto sendit;
 
 err_bad_prog:
-	dprintk("svc: unknown program %d\n", prog);
+	trace_svc_decode_prog_unavail_err(rqstp, prog);
 	serv->sv_stats->rpcbadfmt++;
 	svc_putnl(resv, RPC_PROG_UNAVAIL);
 	goto sendit;

[PATCH v1 10/14] SUNRPC: Report RPC messages with unknown versions via a tracepoint

[Chuck Lever]

Replace a dprintk call site. The new tracepoint can be left enabled
persistently to capture problems.

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 include/trace/events/sunrpc.h |   28 ++++++++++++++++++++++++++++
 net/sunrpc/svc.c              |    4 +---
 2 files changed, 29 insertions(+), 3 deletions(-)

diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h
index db581a837f1b..804912b26abb 100644
--- a/include/trace/events/sunrpc.h
+++ b/include/trace/events/sunrpc.h
@@ -1688,6 +1688,34 @@ TRACE_EVENT(svc_decode_prog_unavail_err,
 	TP_printk("addr=%s program=%u", __get_str(addr), __entry->program)
 );
 
+TRACE_EVENT(svc_decode_prog_mismatch_err,
+	TP_PROTO(
+		const struct svc_rqst *rqst,
+		const struct svc_program *progp
+	),
+
+	TP_ARGS(rqst, progp),
+
+	TP_STRUCT__entry(
+		__field(u32, version)
+		__string(progname, progp->pg_name)
+		__string(addr, rqst->rq_xprt ?
+			 rqst->rq_xprt->xpt_remotebuf : "(null)")
+	),
+
+	TP_fast_assign(
+		__entry->version = rqst->rq_vers;
+		__assign_str(progname, progp->pg_name)
+		__assign_str(addr, rqst->rq_xprt ?
+			     rqst->rq_xprt->xpt_remotebuf : "(null)");
+	),
+
+	TP_printk("addr=%s %sv%u",
+		__get_str(addr), __get_str(progname),
+		__entry->version
+	)
+);
+
 DECLARE_EVENT_CLASS(svc_rqst_event,
 
 	TP_PROTO(
diff --git a/net/sunrpc/svc.c b/net/sunrpc/svc.c
index a057d1373579..66e46d7755e9 100644
--- a/net/sunrpc/svc.c
+++ b/net/sunrpc/svc.c
@@ -1406,9 +1406,7 @@ svc_process_common(struct svc_rqst *rqstp, struct kvec *argv, struct kvec *resv)
 	goto sendit;
 
 err_bad_vers:
-	svc_printk(rqstp, "unknown version (%d for prog %d, %s)\n",
-		       rqstp->rq_vers, rqstp->rq_prog, progp->pg_name);
-
+	trace_svc_decode_prog_mismatch_err(rqstp, progp);
 	serv->sv_stats->rpcbadfmt++;
 	svc_putnl(resv, RPC_PROG_MISMATCH);
 	svc_putnl(resv, process.mismatch.lovers);

[PATCH v1 11/14] SUNRPC: Report RPC messages with unknown procedures via a tracepoint

[Chuck Lever]

Replace a dprintk call site. The new tracepoint can be left enabled
persistently to capture problems.

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 include/trace/events/sunrpc.h |   30 ++++++++++++++++++++++++++++++
 net/sunrpc/svc.c              |    3 +--
 2 files changed, 31 insertions(+), 2 deletions(-)

diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h
index 804912b26abb..85459c40eb35 100644
--- a/include/trace/events/sunrpc.h
+++ b/include/trace/events/sunrpc.h
@@ -1716,6 +1716,36 @@ TRACE_EVENT(svc_decode_prog_mismatch_err,
 	)
 );
 
+TRACE_EVENT(svc_decode_proc_unavail_err,
+	TP_PROTO(
+		const struct svc_rqst *rqst,
+		const struct svc_program *progp
+	),
+
+	TP_ARGS(rqst, progp),
+
+	TP_STRUCT__entry(
+		__field(u32, procedure)
+		__field(u32, version)
+		__string(progname, progp->pg_name)
+		__string(addr, rqst->rq_xprt ?
+			 rqst->rq_xprt->xpt_remotebuf : "(null)")
+	),
+
+	TP_fast_assign(
+		__entry->version = rqst->rq_vers;
+		__entry->procedure = rqst->rq_proc;
+		__assign_str(progname, progp->pg_name)
+		__assign_str(addr, rqst->rq_xprt ?
+			     rqst->rq_xprt->xpt_remotebuf : "(null)");
+	),
+
+	TP_printk("addr=%s %sv%u procedure=%u",
+		__get_str(addr), __get_str(progname),
+		__entry->version, __entry->procedure
+	)
+);
+
 DECLARE_EVENT_CLASS(svc_rqst_event,
 
 	TP_PROTO(
diff --git a/net/sunrpc/svc.c b/net/sunrpc/svc.c
index 66e46d7755e9..a0f37e89393f 100644
--- a/net/sunrpc/svc.c
+++ b/net/sunrpc/svc.c
@@ -1414,8 +1414,7 @@ svc_process_common(struct svc_rqst *rqstp, struct kvec *argv, struct kvec *resv)
 	goto sendit;
 
 err_bad_proc:
-	svc_printk(rqstp, "unknown procedure (%d)\n", rqstp->rq_proc);
-
+	trace_svc_decode_proc_unavail_err(rqstp, progp);
 	serv->sv_stats->rpcbadfmt++;
 	svc_putnl(resv, RPC_PROC_UNAVAIL);
 	goto sendit;

[PATCH v1 12/14] SUNRPC: Report RPC messages that can't be decoded via a tracepoint

[Chuck Lever]

Replace a dprintk call site. The new tracepoint can be left enabled
persistently to capture problems.

This commit removes the last remaining call site for svc_printk(),
so that function is removed as well.

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 include/trace/events/sunrpc.h |   20 ++++++++++++++++++++
 net/sunrpc/svc.c              |   29 +----------------------------
 2 files changed, 21 insertions(+), 28 deletions(-)

diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h
index 85459c40eb35..9d0e7904230e 100644
--- a/include/trace/events/sunrpc.h
+++ b/include/trace/events/sunrpc.h
@@ -1746,6 +1746,26 @@ TRACE_EVENT(svc_decode_proc_unavail_err,
 	)
 );
 
+TRACE_EVENT(svc_decode_header_err,
+	TP_PROTO(
+		const struct svc_rqst *rqst
+	),
+
+	TP_ARGS(rqst),
+
+	TP_STRUCT__entry(
+		__string(addr, rqst->rq_xprt ?
+			 rqst->rq_xprt->xpt_remotebuf : "(null)")
+	),
+
+	TP_fast_assign(
+		__assign_str(addr, rqst->rq_xprt ?
+			     rqst->rq_xprt->xpt_remotebuf : "(null)");
+	),
+
+	TP_printk("addr=%s", __get_str(addr))
+);
+
 DECLARE_EVENT_CLASS(svc_rqst_event,
 
 	TP_PROTO(
diff --git a/net/sunrpc/svc.c b/net/sunrpc/svc.c
index a0f37e89393f..ae3c2d31d6dc 100644
--- a/net/sunrpc/svc.c
+++ b/net/sunrpc/svc.c
@@ -33,8 +33,6 @@
 
 #include "fail.h"
 
-#define RPCDBG_FACILITY	RPCDBG_SVCDSP
-
 static void svc_unregister(const struct svc_serv *serv, struct net *net);
 
 #define svc_serv_is_pooled(serv)    ((serv)->sv_ops->svo_function)
@@ -1156,30 +1154,6 @@ static void svc_unregister(const struct svc_serv *serv, struct net *net)
 	spin_unlock_irqrestore(&current->sighand->siglock, flags);
 }
 
-/*
- * dprintk the given error with the address of the client that caused it.
- */
-#if IS_ENABLED(CONFIG_SUNRPC_DEBUG)
-static __printf(2, 3)
-void svc_printk(struct svc_rqst *rqstp, const char *fmt, ...)
-{
-	struct va_format vaf;
-	va_list args;
-	char 	buf[RPC_MAX_ADDRBUFLEN];
-
-	va_start(args, fmt);
-
-	vaf.fmt = fmt;
-	vaf.va = &args;
-
-	dprintk("svc: %s: %pV", svc_print_addr(rqstp, buf, sizeof(buf)), &vaf);
-
-	va_end(args);
-}
-#else
-static __printf(2,3) void svc_printk(struct svc_rqst *rqstp, const char *fmt, ...) {}
-#endif
-
 __be32
 svc_generic_init_request(struct svc_rqst *rqstp,
 		const struct svc_program *progp,
@@ -1420,8 +1394,7 @@ svc_process_common(struct svc_rqst *rqstp, struct kvec *argv, struct kvec *resv)
 	goto sendit;
 
 err_garbage:
-	svc_printk(rqstp, "failed to decode args\n");
-
+	trace_svc_decode_header_err(rqstp);
 	rpc_stat = rpc_garbage_args;
 err_bad:
 	serv->sv_stats->rpcbadfmt++;

[PATCH v1 13/14] SUNRPC: Fix kdoc comment for svc_unregister()

[Chuck Lever]

Clean up. Commit b4af59328c25 ("SUNRPC: Trace server-side rpcbind
registration events") replaced the dprintk call site in
svc_unregister() but didn't update the function's documenting
comment.

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 net/sunrpc/svc.c |    3 ---
 1 file changed, 3 deletions(-)

diff --git a/net/sunrpc/svc.c b/net/sunrpc/svc.c
index ae3c2d31d6dc..e0773a85dbe5 100644
--- a/net/sunrpc/svc.c
+++ b/net/sunrpc/svc.c
@@ -1127,9 +1127,6 @@ static void __svc_unregister(struct net *net, const u32 program, const u32 versi
  * All netids, bind addresses and ports registered for [program, version]
  * are removed from the local rpcbind database (if the service is not
  * hidden) to make way for a new instance of the service.
- *
- * The result of unregistration is reported via dprintk for those who want
- * verification of the result, but is otherwise not important.
  */
 static void svc_unregister(const struct svc_serv *serv, struct net *net)
 {

[PATCH v1 14/14] SUNRPC: Yank some low-value dprintk call sites

[Chuck Lever]

Deprecation. These can be replaced by function-boundary tracing.

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 net/sunrpc/svc_xprt.c |   19 -------------------
 1 file changed, 19 deletions(-)

diff --git a/net/sunrpc/svc_xprt.c b/net/sunrpc/svc_xprt.c
index 1e99ba1b9d72..f40b88eb5e12 100644
--- a/net/sunrpc/svc_xprt.c
+++ b/net/sunrpc/svc_xprt.c
@@ -20,8 +20,6 @@
 #include <linux/netdevice.h>
 #include <trace/events/sunrpc.h>
 
-#define RPCDBG_FACILITY	RPCDBG_SVCXPRT
-
 static unsigned int svc_rpc_per_connection_limit __read_mostly;
 module_param(svc_rpc_per_connection_limit, uint, 0644);
 
@@ -78,8 +76,6 @@ int svc_reg_xprt_class(struct svc_xprt_class *xcl)
 	struct svc_xprt_class *cl;
 	int res = -EEXIST;
 
-	dprintk("svc: Adding svc transport class '%s'\n", xcl->xcl_name);
-
 	INIT_LIST_HEAD(&xcl->xcl_list);
 	spin_lock(&svc_xprt_class_lock);
 	/* Make sure there isn't already a class with the same name */
@@ -97,7 +93,6 @@ EXPORT_SYMBOL_GPL(svc_reg_xprt_class);
 
 void svc_unreg_xprt_class(struct svc_xprt_class *xcl)
 {
-	dprintk("svc: Removing svc transport class '%s'\n", xcl->xcl_name);
 	spin_lock(&svc_xprt_class_lock);
 	list_del_init(&xcl->xcl_list);
 	spin_unlock(&svc_xprt_class_lock);
@@ -829,9 +824,6 @@ static int svc_handle_xprt(struct svc_rqst *rqstp, struct svc_xprt *xprt)
 		svc_xprt_received(xprt);
 	} else if (svc_xprt_reserve_slot(rqstp, xprt)) {
 		/* XPT_DATA|XPT_DEFERRED case: */
-		dprintk("svc: server %p, pool %u, transport %p, inuse=%d\n",
-			rqstp, rqstp->rq_pool->sp_id, xprt,
-			kref_read(&xprt->xpt_ref));
 		rqstp->rq_deferred = svc_deferred_dequeue(xprt);
 		if (rqstp->rq_deferred)
 			len = svc_deferred_recv(rqstp);
@@ -951,11 +943,8 @@ static void svc_age_temp_xprts(struct timer_list *t)
 	struct svc_xprt *xprt;
 	struct list_head *le, *next;
 
-	dprintk("svc_age_temp_xprts\n");
-
 	if (!spin_trylock_bh(&serv->sv_lock)) {
 		/* busy, try again 1 sec later */
-		dprintk("svc_age_temp_xprts: busy\n");
 		mod_timer(&serv->sv_temptimer, jiffies + HZ);
 		return;
 	}
@@ -972,7 +961,6 @@ static void svc_age_temp_xprts(struct timer_list *t)
 			continue;
 		list_del_init(le);
 		set_bit(XPT_CLOSE, &xprt->xpt_flags);
-		dprintk("queuing xprt %p for closing\n", xprt);
 
 		/* a thread will dequeue and close it soon */
 		svc_xprt_enqueue(xprt);
@@ -999,7 +987,6 @@ void svc_age_temp_xprts_now(struct svc_serv *serv, struct sockaddr *server_addr)
 		xprt = list_entry(le, struct svc_xprt, xpt_list);
 		if (rpc_cmp_addr(server_addr, (struct sockaddr *)
 				&xprt->xpt_local)) {
-			dprintk("svc_age_temp_xprts_now: found %p\n", xprt);
 			list_move(le, &to_be_closed);
 		}
 	}
@@ -1011,8 +998,6 @@ void svc_age_temp_xprts_now(struct svc_serv *serv, struct sockaddr *server_addr)
 		xprt = list_entry(le, struct svc_xprt, xpt_list);
 		set_bit(XPT_CLOSE, &xprt->xpt_flags);
 		set_bit(XPT_KILL_TEMP, &xprt->xpt_flags);
-		dprintk("svc_age_temp_xprts_now: queuing xprt %p for closing\n",
-				xprt);
 		svc_xprt_enqueue(xprt);
 	}
 }
@@ -1386,8 +1371,6 @@ static void *svc_pool_stats_start(struct seq_file *m, loff_t *pos)
 	unsigned int pidx = (unsigned int)*pos;
 	struct svc_serv *serv = m->private;
 
-	dprintk("svc_pool_stats_start, *pidx=%u\n", pidx);
-
 	if (!pidx)
 		return SEQ_START_TOKEN;
 	return (pidx > serv->sv_nrpools ? NULL : &serv->sv_pools[pidx-1]);
@@ -1398,8 +1381,6 @@ static void *svc_pool_stats_next(struct seq_file *m, void *p, loff_t *pos)
 	struct svc_pool *pool = p;
 	struct svc_serv *serv = m->private;
 
-	dprintk("svc_pool_stats_next, *pos=%llu\n", *pos);
-
 	if (p == SEQ_START_TOKEN) {
 		pool = &serv->sv_pools[0];
 	} else {