[PATCH v2 00/25] NFSD callback and lease management observability

[PATCH v2 00/25] NFSD callback and lease management observability

[Chuck Lever]

I've hacked together some improvements to the tracepoints that record
server callback and lease management activity. I'm interested in
review comments and testing. I'm sure I've missed your favorite edge
case, so please let me know what it is!


Changes since RFC:
- Rebased firmly on v5.13-rc1
- Re-organized the SETCLIENTID/EXCHANGE_ID tracepoints
- Fixed/replaced the use of '%.*s'
- Re-ordered the series so those fixes come first

In fact I'd like to submit the first 5 patches for v5.13-rc.

---

Chuck Lever (25):
      NFSD: Fix TP_printk() format specifier in trace_nfsd_dirent()
      NFSD: Fix TP_printk() format specifier in nfsd_clid_class
      NFSD: Add nfsd_clid_cred_mismatch tracepoint
      NFSD: Add nfsd_clid_verf_mismatch tracepoint
      NFSD: Remove trace_nfsd_clid_inuse_err
      NFSD: Add nfsd_clid_confirmed tracepoint
      NFSD: Add nfsd_clid_reclaim_complete tracepoint
      NFSD: Add nfsd_clid_destroyed tracepoint
      NFSD: Add a couple more nfsd_clid_expired call sites
      NFSD: Add an RPC authflavor tracepoint display helper
      NFSD: Add tracepoints for SETCLIENTID edge cases
      NFSD: Add tracepoints for EXCHANGEID edge cases
      NFSD: Constify @fh argument of knfsd_fh_hash()
      NFSD: Capture every CB state transition
      NFSD: Drop TRACE_DEFINE_ENUM for NFSD4_CB_<state> macros
      NFSD: Add cb_lost tracepoint
      NFSD: Adjust cb_shutdown tracepoint
      NFSD: Remove spurious cb_setup_err tracepoint
      NFSD: Enhance the nfsd_cb_setup tracepoint
      NFSD: Add an nfsd_cb_lm_notify tracepoint
      NFSD: Add an nfsd_cb_offload tracepoint
      NFSD: Replace the nfsd_deleg_break tracepoint
      NFSD: Add an nfsd_cb_probe tracepoint
      NFSD: Remove the nfsd_cb_work and nfsd_cb_done tracepoints
      NFSD: Update nfsd_cb_args tracepoint


 fs/nfsd/nfs4callback.c |  45 ++++----
 fs/nfsd/nfs4proc.c     |   1 +
 fs/nfsd/nfs4state.c    |  82 ++++++++-----
 fs/nfsd/nfsfh.h        |   7 +-
 fs/nfsd/trace.h        | 254 ++++++++++++++++++++++++++++++-----------
 5 files changed, 264 insertions(+), 125 deletions(-)

--
Chuck Lever

[PATCH v2 01/25] NFSD: Fix TP_printk() format specifier in trace_nfsd_dirent()

[Chuck Lever]

Since commit 9a6944fee68e ("tracing: Add a verifier to check string
pointers for trace events"), which was merged in v5.13-rc1,
TP_printk() no longer tacitly supports the "%.*s" format specifier.

Note that __string() and __assign_str() cannot be used for
non-NUL-terminated C strings because they perform a strlen() on
the string that is to be copied.

Instead, memcpy the whole file name into the record, but display
just the part up to the first NUL. In almost every case that will
show the whole file name.

Reported-by: David Wysochanski <dwysocha@redhat.com>
Fixes: 6019ce0742ca ("NFSD: Add a tracepoint to record directory entry encoding")
Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
Cc: Steven Rostedt <rostedt@goodmis.org>
---
 fs/nfsd/trace.h |   12 +++++-------
 1 file changed, 5 insertions(+), 7 deletions(-)

diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h
index 27a93ebd1d80..781af519b40c 100644
--- a/fs/nfsd/trace.h
+++ b/fs/nfsd/trace.h
@@ -400,19 +400,17 @@ TRACE_EVENT(nfsd_dirent,
 	TP_STRUCT__entry(
 		__field(u32, fh_hash)
 		__field(u64, ino)
-		__field(int, len)
-		__dynamic_array(unsigned char, name, namlen)
+		__dynamic_array(char, name, namlen + 1)
 	),
 	TP_fast_assign(
 		__entry->fh_hash = fhp ? knfsd_fh_hash(&fhp->fh_handle) : 0;
 		__entry->ino = ino;
-		__entry->len = namlen;
 		memcpy(__get_str(name), name, namlen);
-		__assign_str(name, name);
+		__get_str(name)[namlen] = '\0';
 	),
-	TP_printk("fh_hash=0x%08x ino=%llu name=%.*s",
-		__entry->fh_hash, __entry->ino,
-		__entry->len, __get_str(name))
+	TP_printk("fh_hash=0x%08x ino=%llu name=%s",
+		__entry->fh_hash, __entry->ino, __get_str(name)
+	)
 )
 
 #include "state.h"

[PATCH v2 02/25] NFSD: Fix TP_printk() format specifier in nfsd_clid_class

[Chuck Lever]

Since commit 9a6944fee68e ("tracing: Add a verifier to check string
pointers for trace events"), which was merged in v5.13-rc1,
TP_printk() no longer tacitly supports the "%.*s" format specifier.

These are low value tracepoints, so just remove them.

Reported-by: David Wysochanski <dwysocha@redhat.com>
Fixes: dd5e3fbc1f47 ("NFSD: Add tracepoints to the NFSD state management code")
Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
Cc: Steven Rostedt <rostedt@goodmis.org>
---
 fs/nfsd/nfs4state.c |    3 ---
 fs/nfsd/trace.h     |   29 -----------------------------
 2 files changed, 32 deletions(-)

diff --git a/fs/nfsd/nfs4state.c b/fs/nfsd/nfs4state.c
index b517a8794400..6abe48dee6ed 100644
--- a/fs/nfsd/nfs4state.c
+++ b/fs/nfsd/nfs4state.c
@@ -7229,7 +7229,6 @@ nfs4_client_to_reclaim(struct xdr_netobj name, struct xdr_netobj princhash,
 	unsigned int strhashval;
 	struct nfs4_client_reclaim *crp;
 
-	trace_nfsd_clid_reclaim(nn, name.len, name.data);
 	crp = alloc_reclaim();
 	if (crp) {
 		strhashval = clientstr_hashval(name);
@@ -7279,8 +7278,6 @@ nfsd4_find_reclaim_client(struct xdr_netobj name, struct nfsd_net *nn)
 	unsigned int strhashval;
 	struct nfs4_client_reclaim *crp = NULL;
 
-	trace_nfsd_clid_find(nn, name.len, name.data);
-
 	strhashval = clientstr_hashval(name);
 	list_for_each_entry(crp, &nn->reclaim_str_hashtbl[strhashval], cr_strhash) {
 		if (compare_blob(&crp->cr_name, &name) == 0) {
diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h
index 781af519b40c..f0ee18202de0 100644
--- a/fs/nfsd/trace.h
+++ b/fs/nfsd/trace.h
@@ -534,35 +534,6 @@ DEFINE_EVENT(nfsd_net_class, nfsd_##name, \
 DEFINE_NET_EVENT(grace_start);
 DEFINE_NET_EVENT(grace_complete);
 
-DECLARE_EVENT_CLASS(nfsd_clid_class,
-	TP_PROTO(const struct nfsd_net *nn,
-		 unsigned int namelen,
-		 const unsigned char *namedata),
-	TP_ARGS(nn, namelen, namedata),
-	TP_STRUCT__entry(
-		__field(unsigned long long, boot_time)
-		__field(unsigned int, namelen)
-		__dynamic_array(unsigned char,  name, namelen)
-	),
-	TP_fast_assign(
-		__entry->boot_time = nn->boot_time;
-		__entry->namelen = namelen;
-		memcpy(__get_dynamic_array(name), namedata, namelen);
-	),
-	TP_printk("boot_time=%16llx nfs4_clientid=%.*s",
-		__entry->boot_time, __entry->namelen, __get_str(name))
-)
-
-#define DEFINE_CLID_EVENT(name) \
-DEFINE_EVENT(nfsd_clid_class, nfsd_clid_##name, \
-	TP_PROTO(const struct nfsd_net *nn, \
-		 unsigned int namelen, \
-		 const unsigned char *namedata), \
-	TP_ARGS(nn, namelen, namedata))
-
-DEFINE_CLID_EVENT(find);
-DEFINE_CLID_EVENT(reclaim);
-
 TRACE_EVENT(nfsd_clid_inuse_err,
 	TP_PROTO(const struct nfs4_client *clp),
 	TP_ARGS(clp),

[PATCH v2 03/25] NFSD: Add nfsd_clid_cred_mismatch tracepoint

[Chuck Lever]

Record when a client tries to establish a lease record but uses an
unexpected credential. This is often a sign of a configuration
problem.

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 fs/nfsd/nfs4state.c |   14 ++++++++++----
 fs/nfsd/trace.h     |   28 ++++++++++++++++++++++++++++
 2 files changed, 38 insertions(+), 4 deletions(-)

diff --git a/fs/nfsd/nfs4state.c b/fs/nfsd/nfs4state.c
index 6abe48dee6ed..84c4021b3826 100644
--- a/fs/nfsd/nfs4state.c
+++ b/fs/nfsd/nfs4state.c
@@ -3181,6 +3181,7 @@ nfsd4_exchange_id(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate,
 		if (!creds_match) { /* case 3 */
 			if (client_has_state(conf)) {
 				status = nfserr_clid_inuse;
+				trace_nfsd_clid_cred_mismatch(conf, rqstp);
 				goto out;
 			}
 			goto out_new;
@@ -3425,9 +3426,10 @@ nfsd4_create_session(struct svc_rqst *rqstp,
 			goto out_free_conn;
 		}
 	} else if (unconf) {
+		status = nfserr_clid_inuse;
 		if (!same_creds(&unconf->cl_cred, &rqstp->rq_cred) ||
 		    !rpc_cmp_addr(sa, (struct sockaddr *) &unconf->cl_addr)) {
-			status = nfserr_clid_inuse;
+			trace_nfsd_clid_cred_mismatch(unconf, rqstp);
 			goto out_free_conn;
 		}
 		status = nfserr_wrong_cred;
@@ -3976,7 +3978,7 @@ nfsd4_setclientid(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate,
 		if (clp_used_exchangeid(conf))
 			goto out;
 		if (!same_creds(&conf->cl_cred, &rqstp->rq_cred)) {
-			trace_nfsd_clid_inuse_err(conf);
+			trace_nfsd_clid_cred_mismatch(conf, rqstp);
 			goto out;
 		}
 	}
@@ -4034,10 +4036,14 @@ nfsd4_setclientid_confirm(struct svc_rqst *rqstp,
 	 * Nevertheless, RFC 7530 recommends INUSE for this case:
 	 */
 	status = nfserr_clid_inuse;
-	if (unconf && !same_creds(&unconf->cl_cred, &rqstp->rq_cred))
+	if (unconf && !same_creds(&unconf->cl_cred, &rqstp->rq_cred)) {
+		trace_nfsd_clid_cred_mismatch(unconf, rqstp);
 		goto out;
-	if (conf && !same_creds(&conf->cl_cred, &rqstp->rq_cred))
+	}
+	if (conf && !same_creds(&conf->cl_cred, &rqstp->rq_cred)) {
+		trace_nfsd_clid_cred_mismatch(conf, rqstp);
 		goto out;
+	}
 	/* cases below refer to rfc 3530 section 14.2.34: */
 	if (!unconf || !same_verf(&confirm, &unconf->cl_confirm)) {
 		if (conf && same_verf(&confirm, &conf->cl_confirm)) {
diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h
index f0ee18202de0..25ed99220c7b 100644
--- a/fs/nfsd/trace.h
+++ b/fs/nfsd/trace.h
@@ -534,6 +534,34 @@ DEFINE_EVENT(nfsd_net_class, nfsd_##name, \
 DEFINE_NET_EVENT(grace_start);
 DEFINE_NET_EVENT(grace_complete);
 
+TRACE_EVENT(nfsd_clid_cred_mismatch,
+	TP_PROTO(
+		const struct nfs4_client *clp,
+		const struct svc_rqst *rqstp
+	),
+	TP_ARGS(clp, rqstp),
+	TP_STRUCT__entry(
+		__field(u32, cl_boot)
+		__field(u32, cl_id)
+		__field(unsigned long, cl_flavor)
+		__field(unsigned long, new_flavor)
+		__array(unsigned char, addr, sizeof(struct sockaddr_in6))
+	),
+	TP_fast_assign(
+		__entry->cl_boot = clp->cl_clientid.cl_boot;
+		__entry->cl_id = clp->cl_clientid.cl_id;
+		__entry->cl_flavor = clp->cl_cred.cr_flavor;
+		__entry->new_flavor = rqstp->rq_cred.cr_flavor;
+		memcpy(__entry->addr, &rqstp->rq_xprt->xpt_remote,
+			sizeof(struct sockaddr_in6));
+	),
+	TP_printk("client %08x:%08x flavor=%s, conflict=%s from addr=%pISpc",
+		__entry->cl_boot, __entry->cl_id,
+		show_nfsd_authflavor(__entry->cl_flavor),
+		show_nfsd_authflavor(__entry->new_flavor), __entry->addr
+	)
+)
+
 TRACE_EVENT(nfsd_clid_inuse_err,
 	TP_PROTO(const struct nfs4_client *clp),
 	TP_ARGS(clp),

[PATCH v2 04/25] NFSD: Add nfsd_clid_verf_mismatch tracepoint

[Chuck Lever]

Record when a client presents a different boot verifier than the
one we know about. Typically this is a sign the client has
rebooted, but sometimes it signals a conflicting client ID, which
the client's administrator will need to address.

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 fs/nfsd/nfs4state.c |   11 ++++++++---
 fs/nfsd/trace.h     |   32 ++++++++++++++++++++++++++++++++
 2 files changed, 40 insertions(+), 3 deletions(-)

diff --git a/fs/nfsd/nfs4state.c b/fs/nfsd/nfs4state.c
index 84c4021b3826..69405cc9d823 100644
--- a/fs/nfsd/nfs4state.c
+++ b/fs/nfsd/nfs4state.c
@@ -3191,6 +3191,7 @@ nfsd4_exchange_id(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate,
 			goto out_copy;
 		}
 		/* case 5, client reboot */
+		trace_nfsd_clid_verf_mismatch(conf, rqstp, &verf);
 		conf = NULL;
 		goto out_new;
 	}
@@ -3986,9 +3987,13 @@ nfsd4_setclientid(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate,
 	if (unconf)
 		unhash_client_locked(unconf);
 	/* We need to handle only case 1: probable callback update */
-	if (conf && same_verf(&conf->cl_verifier, &clverifier)) {
-		copy_clid(new, conf);
-		gen_confirm(new, nn);
+	if (conf) {
+		if (same_verf(&conf->cl_verifier, &clverifier)) {
+			copy_clid(new, conf);
+			gen_confirm(new, nn);
+		} else
+			trace_nfsd_clid_verf_mismatch(conf, rqstp,
+						      &clverifier);
 	}
 	new->cl_minorversion = 0;
 	gen_callback(new, setclid, rqstp);
diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h
index 25ed99220c7b..7e2fce504a2d 100644
--- a/fs/nfsd/trace.h
+++ b/fs/nfsd/trace.h
@@ -562,6 +562,38 @@ TRACE_EVENT(nfsd_clid_cred_mismatch,
 	)
 )
 
+TRACE_EVENT(nfsd_clid_verf_mismatch,
+	TP_PROTO(
+		const struct nfs4_client *clp,
+		const struct svc_rqst *rqstp,
+		const nfs4_verifier *verf
+	),
+	TP_ARGS(clp, rqstp, verf),
+	TP_STRUCT__entry(
+		__field(u32, cl_boot)
+		__field(u32, cl_id)
+		__array(unsigned char, cl_verifier, NFS4_VERIFIER_SIZE)
+		__array(unsigned char, new_verifier, NFS4_VERIFIER_SIZE)
+		__array(unsigned char, addr, sizeof(struct sockaddr_in6))
+	),
+	TP_fast_assign(
+		__entry->cl_boot = clp->cl_clientid.cl_boot;
+		__entry->cl_id = clp->cl_clientid.cl_id;
+		memcpy(__entry->cl_verifier, (void *)&clp->cl_verifier,
+		       NFS4_VERIFIER_SIZE);
+		memcpy(__entry->new_verifier, (void *)verf,
+		       NFS4_VERIFIER_SIZE);
+		memcpy(__entry->addr, &rqstp->rq_xprt->xpt_remote,
+			sizeof(struct sockaddr_in6));
+	),
+	TP_printk("client %08x:%08x verf=0x%s, updated=0x%s from addr=%pISpc",
+		__entry->cl_boot, __entry->cl_id,
+		__print_hex_str(__entry->cl_verifier, NFS4_VERIFIER_SIZE),
+		__print_hex_str(__entry->new_verifier, NFS4_VERIFIER_SIZE),
+		__entry->addr
+	)
+);
+
 TRACE_EVENT(nfsd_clid_inuse_err,
 	TP_PROTO(const struct nfs4_client *clp),
 	TP_ARGS(clp),

[PATCH v2 05/25] NFSD: Remove trace_nfsd_clid_inuse_err

[Chuck Lever]

Since commit 9a6944fee68e ("tracing: Add a verifier to check string
pointers for trace events"), which was merged in v5.13-rc1,
TP_printk() no longer tacitly supports the "%.*s" format specifier.

This tracepoint has been replaced by nfsd_clid_cred_mismatch and
nfsd_clid_verf_mismatch, and can simply be removed.

Reported-by: David Wysochanski <dwysocha@redhat.com>
Fixes: dd5e3fbc1f47 ("NFSD: Add tracepoints to the NFSD state management code")
Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
Cc: Steven Rostedt <rostedt@goodmis.org>
---
 fs/nfsd/trace.h |   24 ------------------------
 1 file changed, 24 deletions(-)

diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h
index 7e2fce504a2d..b5bf792575d5 100644
--- a/fs/nfsd/trace.h
+++ b/fs/nfsd/trace.h
@@ -594,30 +594,6 @@ TRACE_EVENT(nfsd_clid_verf_mismatch,
 	)
 );
 
-TRACE_EVENT(nfsd_clid_inuse_err,
-	TP_PROTO(const struct nfs4_client *clp),
-	TP_ARGS(clp),
-	TP_STRUCT__entry(
-		__field(u32, cl_boot)
-		__field(u32, cl_id)
-		__array(unsigned char, addr, sizeof(struct sockaddr_in6))
-		__field(unsigned int, namelen)
-		__dynamic_array(unsigned char, name, clp->cl_name.len)
-	),
-	TP_fast_assign(
-		__entry->cl_boot = clp->cl_clientid.cl_boot;
-		__entry->cl_id = clp->cl_clientid.cl_id;
-		memcpy(__entry->addr, &clp->cl_addr,
-			sizeof(struct sockaddr_in6));
-		__entry->namelen = clp->cl_name.len;
-		memcpy(__get_dynamic_array(name), clp->cl_name.data,
-			clp->cl_name.len);
-	),
-	TP_printk("nfs4_clientid %.*s already in use by %pISpc, client %08x:%08x",
-		__entry->namelen, __get_str(name), __entry->addr,
-		__entry->cl_boot, __entry->cl_id)
-)
-
 /*
  * from fs/nfsd/filecache.h
  */

[PATCH v2 06/25] NFSD: Add nfsd_clid_confirmed tracepoint

[Chuck Lever]

This replaces a dprintk call site in order to get greater visibility
on when client IDs are confirmed or re-used. Simple example:

            nfsd-995   [000]   126.622975: nfsd_compound:        xid=0x3a34e2b1 opcnt=1
            nfsd-995   [000]   126.623005: nfsd_cb_args:         addr=192.168.2.51:45901 client 60958e3b:9213ef0e prog=1073741824 ident=1
            nfsd-995   [000]   126.623007: nfsd_compound_status: op=1/1 OP_SETCLIENTID status=0
            nfsd-996   [001]   126.623142: nfsd_compound:        xid=0x3b34e2b1 opcnt=1
  >>>>      nfsd-996   [001]   126.623146: nfsd_clid_confirmed:  client 60958e3b:9213ef0e
            nfsd-996   [001]   126.623148: nfsd_cb_probe:        addr=192.168.2.51:45901 client 60958e3b:9213ef0e state=UNKNOWN
            nfsd-996   [001]   126.623154: nfsd_compound_status: op=1/1 OP_SETCLIENTID_CONFIRM status=0

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 fs/nfsd/nfs4state.c |   10 +++++-----
 fs/nfsd/trace.h     |    1 +
 2 files changed, 6 insertions(+), 5 deletions(-)

diff --git a/fs/nfsd/nfs4state.c b/fs/nfsd/nfs4state.c
index 69405cc9d823..37cef1f498e1 100644
--- a/fs/nfsd/nfs4state.c
+++ b/fs/nfsd/nfs4state.c
@@ -2816,14 +2816,14 @@ move_to_confirmed(struct nfs4_client *clp)
 
 	lockdep_assert_held(&nn->client_lock);
 
-	dprintk("NFSD: move_to_confirm nfs4_client %p\n", clp);
 	list_move(&clp->cl_idhash, &nn->conf_id_hashtbl[idhashval]);
 	rb_erase(&clp->cl_namenode, &nn->unconf_name_tree);
 	add_clp_to_name_tree(clp, &nn->conf_name_tree);
-	if (!test_and_set_bit(NFSD4_CLIENT_CONFIRMED, &clp->cl_flags) &&
-	    clp->cl_nfsd_dentry &&
-	    clp->cl_nfsd_info_dentry)
-		fsnotify_dentry(clp->cl_nfsd_info_dentry, FS_MODIFY);
+	if (!test_and_set_bit(NFSD4_CLIENT_CONFIRMED, &clp->cl_flags)) {
+		trace_nfsd_clid_confirmed(&clp->cl_clientid);
+		if (clp->cl_nfsd_dentry && clp->cl_nfsd_info_dentry)
+			fsnotify_dentry(clp->cl_nfsd_info_dentry, FS_MODIFY);
+	}
 	renew_client_locked(clp);
 }
 
diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h
index b5bf792575d5..c0cf98f6da63 100644
--- a/fs/nfsd/trace.h
+++ b/fs/nfsd/trace.h
@@ -509,6 +509,7 @@ DEFINE_EVENT(nfsd_clientid_class, nfsd_clid_##name, \
 	TP_PROTO(const clientid_t *clid), \
 	TP_ARGS(clid))
 
+DEFINE_CLIENTID_EVENT(confirmed);
 DEFINE_CLIENTID_EVENT(expired);
 DEFINE_CLIENTID_EVENT(purged);
 DEFINE_CLIENTID_EVENT(renew);

[PATCH v2 07/25] NFSD: Add nfsd_clid_reclaim_complete tracepoint

[Chuck Lever]

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 fs/nfsd/nfs4state.c |    1 +
 fs/nfsd/trace.h     |    1 +
 2 files changed, 2 insertions(+)

diff --git a/fs/nfsd/nfs4state.c b/fs/nfsd/nfs4state.c
index 37cef1f498e1..03f2770c815f 100644
--- a/fs/nfsd/nfs4state.c
+++ b/fs/nfsd/nfs4state.c
@@ -3949,6 +3949,7 @@ nfsd4_reclaim_complete(struct svc_rqst *rqstp,
 		goto out;
 
 	status = nfs_ok;
+	trace_nfsd_clid_reclaim_complete(&clp->cl_clientid);
 	nfsd4_client_record_create(clp);
 	inc_reclaim_complete(clp);
 out:
diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h
index c0cf98f6da63..2f7d111461d0 100644
--- a/fs/nfsd/trace.h
+++ b/fs/nfsd/trace.h
@@ -509,6 +509,7 @@ DEFINE_EVENT(nfsd_clientid_class, nfsd_clid_##name, \
 	TP_PROTO(const clientid_t *clid), \
 	TP_ARGS(clid))
 
+DEFINE_CLIENTID_EVENT(reclaim_complete);
 DEFINE_CLIENTID_EVENT(confirmed);
 DEFINE_CLIENTID_EVENT(expired);
 DEFINE_CLIENTID_EVENT(purged);

[PATCH v2 08/25] NFSD: Add nfsd_clid_destroyed tracepoint

[Chuck Lever]

Record client-requested termination of client IDs.

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 fs/nfsd/nfs4state.c |    1 +
 fs/nfsd/trace.h     |    1 +
 2 files changed, 2 insertions(+)

diff --git a/fs/nfsd/nfs4state.c b/fs/nfsd/nfs4state.c
index 03f2770c815f..08ff643e96fb 100644
--- a/fs/nfsd/nfs4state.c
+++ b/fs/nfsd/nfs4state.c
@@ -3907,6 +3907,7 @@ nfsd4_destroy_clientid(struct svc_rqst *rqstp,
 		status = nfserr_wrong_cred;
 		goto out;
 	}
+	trace_nfsd_clid_destroyed(&clp->cl_clientid);
 	unhash_client_locked(clp);
 out:
 	spin_unlock(&nn->client_lock);
diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h
index 2f7d111461d0..cef826f64575 100644
--- a/fs/nfsd/trace.h
+++ b/fs/nfsd/trace.h
@@ -511,6 +511,7 @@ DEFINE_EVENT(nfsd_clientid_class, nfsd_clid_##name, \
 
 DEFINE_CLIENTID_EVENT(reclaim_complete);
 DEFINE_CLIENTID_EVENT(confirmed);
+DEFINE_CLIENTID_EVENT(destroyed);
 DEFINE_CLIENTID_EVENT(expired);
 DEFINE_CLIENTID_EVENT(purged);
 DEFINE_CLIENTID_EVENT(renew);

[PATCH v2 09/25] NFSD: Add a couple more nfsd_clid_expired call sites

[Chuck Lever]

Improve observation of NFSv4 lease expiry.

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 fs/nfsd/nfs4state.c |    3 +++
 1 file changed, 3 insertions(+)

diff --git a/fs/nfsd/nfs4state.c b/fs/nfsd/nfs4state.c
index 08ff643e96fb..7fa90a3177fa 100644
--- a/fs/nfsd/nfs4state.c
+++ b/fs/nfsd/nfs4state.c
@@ -2665,6 +2665,8 @@ static void force_expire_client(struct nfs4_client *clp)
 	struct nfsd_net *nn = net_generic(clp->net, nfsd_net_id);
 	bool already_expired;
 
+	trace_nfsd_clid_expired(&clp->cl_clientid);
+
 	spin_lock(&clp->cl_lock);
 	clp->cl_time = 0;
 	spin_unlock(&clp->cl_lock);
@@ -4075,6 +4077,7 @@ nfsd4_setclientid_confirm(struct svc_rqst *rqstp,
 				goto out;
 			status = mark_client_expired_locked(old);
 			if (status) {
+				trace_nfsd_clid_expired(&old->cl_clientid);
 				old = NULL;
 				goto out;
 			}

[PATCH v2 10/25] NFSD: Add an RPC authflavor tracepoint display helper

[Chuck Lever]

To be used in subsequent patches.

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

diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h
index cef826f64575..7ccf17077c3b 100644
--- a/fs/nfsd/trace.h
+++ b/fs/nfsd/trace.h
@@ -878,6 +878,22 @@ DEFINE_NFSD_CB_EVENT(setup);
 DEFINE_NFSD_CB_EVENT(state);
 DEFINE_NFSD_CB_EVENT(shutdown);
 
+TRACE_DEFINE_ENUM(RPC_AUTH_NULL);
+TRACE_DEFINE_ENUM(RPC_AUTH_UNIX);
+TRACE_DEFINE_ENUM(RPC_AUTH_GSS);
+TRACE_DEFINE_ENUM(RPC_AUTH_GSS_KRB5);
+TRACE_DEFINE_ENUM(RPC_AUTH_GSS_KRB5I);
+TRACE_DEFINE_ENUM(RPC_AUTH_GSS_KRB5P);
+
+#define show_nfsd_authflavor(val)					\
+	__print_symbolic(val,						\
+		{ RPC_AUTH_NULL,		"none" },		\
+		{ RPC_AUTH_UNIX,		"sys" },		\
+		{ RPC_AUTH_GSS,			"gss" },		\
+		{ RPC_AUTH_GSS_KRB5,		"krb5" },		\
+		{ RPC_AUTH_GSS_KRB5I,		"krb5i" },		\
+		{ RPC_AUTH_GSS_KRB5P,		"krb5p" })
+
 TRACE_EVENT(nfsd_cb_setup_err,
 	TP_PROTO(
 		const struct nfs4_client *clp,

[PATCH v2 11/25] NFSD: Add tracepoints for SETCLIENTID edge cases

[Chuck Lever]

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 fs/nfsd/nfs4state.c |   19 ++++++++-----------
 fs/nfsd/trace.h     |   37 +++++++++++++++++++++++++++++++++++++
 2 files changed, 45 insertions(+), 11 deletions(-)

diff --git a/fs/nfsd/nfs4state.c b/fs/nfsd/nfs4state.c
index 7fa90a3177fa..e38cf9c236f1 100644
--- a/fs/nfsd/nfs4state.c
+++ b/fs/nfsd/nfs4state.c
@@ -3974,11 +3974,9 @@ nfsd4_setclientid(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate,
 	new = create_client(clname, rqstp, &clverifier);
 	if (new == NULL)
 		return nfserr_jukebox;
-	/* Cases below refer to rfc 3530 section 14.2.33: */
 	spin_lock(&nn->client_lock);
 	conf = find_confirmed_client_by_name(&clname, nn);
 	if (conf && client_has_state(conf)) {
-		/* case 0: */
 		status = nfserr_clid_inuse;
 		if (clp_used_exchangeid(conf))
 			goto out;
@@ -3990,7 +3988,6 @@ nfsd4_setclientid(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate,
 	unconf = find_unconfirmed_client_by_name(&clname, nn);
 	if (unconf)
 		unhash_client_locked(unconf);
-	/* We need to handle only case 1: probable callback update */
 	if (conf) {
 		if (same_verf(&conf->cl_verifier, &clverifier)) {
 			copy_clid(new, conf);
@@ -3998,7 +3995,8 @@ nfsd4_setclientid(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate,
 		} else
 			trace_nfsd_clid_verf_mismatch(conf, rqstp,
 						      &clverifier);
-	}
+	} else
+		trace_nfsd_clid_fresh(new);
 	new->cl_minorversion = 0;
 	gen_callback(new, setclid, rqstp);
 	add_to_unconfirmed(new);
@@ -4011,12 +4009,13 @@ nfsd4_setclientid(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate,
 	spin_unlock(&nn->client_lock);
 	if (new)
 		free_client(new);
-	if (unconf)
+	if (unconf) {
+		trace_nfsd_clid_expire_unconf(&unconf->cl_clientid);
 		expire_client(unconf);
+	}
 	return status;
 }
 
-
 __be32
 nfsd4_setclientid_confirm(struct svc_rqst *rqstp,
 			struct nfsd4_compound_state *cstate,
@@ -4053,21 +4052,19 @@ nfsd4_setclientid_confirm(struct svc_rqst *rqstp,
 		trace_nfsd_clid_cred_mismatch(conf, rqstp);
 		goto out;
 	}
-	/* cases below refer to rfc 3530 section 14.2.34: */
 	if (!unconf || !same_verf(&confirm, &unconf->cl_confirm)) {
 		if (conf && same_verf(&confirm, &conf->cl_confirm)) {
-			/* case 2: probable retransmit */
 			status = nfs_ok;
-		} else /* case 4: client hasn't noticed we rebooted yet? */
+		} else
 			status = nfserr_stale_clientid;
 		goto out;
 	}
 	status = nfs_ok;
-	if (conf) { /* case 1: callback update */
+	if (conf) {
 		old = unconf;
 		unhash_client_locked(old);
 		nfsd4_change_callback(conf, &unconf->cl_cb_conn);
-	} else { /* case 3: normal case; new or rebooted client */
+	} else {
 		old = find_confirmed_client_by_name(&unconf->cl_name, nn);
 		if (old) {
 			status = nfserr_clid_inuse;
diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h
index 7ccf17077c3b..2be1881f05e6 100644
--- a/fs/nfsd/trace.h
+++ b/fs/nfsd/trace.h
@@ -509,6 +509,7 @@ DEFINE_EVENT(nfsd_clientid_class, nfsd_clid_##name, \
 	TP_PROTO(const clientid_t *clid), \
 	TP_ARGS(clid))
 
+DEFINE_CLIENTID_EVENT(expire_unconf);
 DEFINE_CLIENTID_EVENT(reclaim_complete);
 DEFINE_CLIENTID_EVENT(confirmed);
 DEFINE_CLIENTID_EVENT(destroyed);
@@ -597,6 +598,42 @@ TRACE_EVENT(nfsd_clid_verf_mismatch,
 	)
 );
 
+DECLARE_EVENT_CLASS(nfsd_clid_class,
+	TP_PROTO(const struct nfs4_client *clp),
+	TP_ARGS(clp),
+	TP_STRUCT__entry(
+		__field(u32, cl_boot)
+		__field(u32, cl_id)
+		__array(unsigned char, addr, sizeof(struct sockaddr_in6))
+		__field(unsigned long, flavor)
+		__array(unsigned char, verifier, NFS4_VERIFIER_SIZE)
+		__dynamic_array(char, name, clp->cl_name.len + 1)
+	),
+	TP_fast_assign(
+		__entry->cl_boot = clp->cl_clientid.cl_boot;
+		__entry->cl_id = clp->cl_clientid.cl_id;
+		memcpy(__entry->addr, &clp->cl_addr,
+			sizeof(struct sockaddr_in6));
+		__entry->flavor = clp->cl_cred.cr_flavor;
+		memcpy(__entry->verifier, (void *)&clp->cl_verifier,
+		       NFS4_VERIFIER_SIZE);
+		memcpy(__get_str(name), clp->cl_name.data, clp->cl_name.len);
+		__get_str(name)[clp->cl_name.len] = '\0';
+	),
+	TP_printk("addr=%pISpc name='%s' verifier=0x%s flavor=%s client=%08x:%08x",
+		__entry->addr, __get_str(name),
+		__print_hex_str(__entry->verifier, NFS4_VERIFIER_SIZE),
+		show_nfsd_authflavor(__entry->flavor),
+		__entry->cl_boot, __entry->cl_id)
+);
+
+#define DEFINE_CLID_EVENT(name) \
+DEFINE_EVENT(nfsd_clid_class, nfsd_clid_##name, \
+	TP_PROTO(const struct nfs4_client *clp), \
+	TP_ARGS(clp))
+
+DEFINE_CLID_EVENT(fresh);
+
 /*
  * from fs/nfsd/filecache.h
  */

[PATCH v2 12/25] NFSD: Add tracepoints for EXCHANGEID edge cases

[Chuck Lever]

Some of the most common cases are traced. Enough infrastructure is
now in place that more can be added later, as needed.

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 fs/nfsd/nfs4state.c |   12 +++++++++---
 fs/nfsd/trace.h     |    1 +
 2 files changed, 10 insertions(+), 3 deletions(-)

diff --git a/fs/nfsd/nfs4state.c b/fs/nfsd/nfs4state.c
index e38cf9c236f1..ad0139b6df15 100644
--- a/fs/nfsd/nfs4state.c
+++ b/fs/nfsd/nfs4state.c
@@ -3178,6 +3178,7 @@ nfsd4_exchange_id(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate,
 			}
 			/* case 6 */
 			exid->flags |= EXCHGID4_FLAG_CONFIRMED_R;
+			trace_nfsd_clid_confirmed_r(conf);
 			goto out_copy;
 		}
 		if (!creds_match) { /* case 3 */
@@ -3190,6 +3191,7 @@ nfsd4_exchange_id(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate,
 		}
 		if (verfs_match) { /* case 2 */
 			conf->cl_exchange_flags |= EXCHGID4_FLAG_CONFIRMED_R;
+			trace_nfsd_clid_confirmed_r(conf);
 			goto out_copy;
 		}
 		/* case 5, client reboot */
@@ -3203,11 +3205,13 @@ nfsd4_exchange_id(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate,
 		goto out;
 	}
 
-	unconf  = find_unconfirmed_client_by_name(&exid->clname, nn);
+	unconf = find_unconfirmed_client_by_name(&exid->clname, nn);
 	if (unconf) /* case 4, possible retry or client restart */
 		unhash_client_locked(unconf);
 
-	/* case 1 (normal case) */
+	/* case 1, new owner ID */
+	trace_nfsd_clid_fresh(new);
+
 out_new:
 	if (conf) {
 		status = mark_client_expired_locked(conf);
@@ -3236,8 +3240,10 @@ nfsd4_exchange_id(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate,
 out_nolock:
 	if (new)
 		expire_client(new);
-	if (unconf)
+	if (unconf) {
+		trace_nfsd_clid_expire_unconf(&unconf->cl_clientid);
 		expire_client(unconf);
+	}
 	return status;
 }
 
diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h
index 2be1881f05e6..7de8ca581c5d 100644
--- a/fs/nfsd/trace.h
+++ b/fs/nfsd/trace.h
@@ -633,6 +633,7 @@ DEFINE_EVENT(nfsd_clid_class, nfsd_clid_##name, \
 	TP_ARGS(clp))
 
 DEFINE_CLID_EVENT(fresh);
+DEFINE_CLID_EVENT(confirmed_r);
 
 /*
  * from fs/nfsd/filecache.h

[PATCH v2 13/25] NFSD: Constify @fh argument of knfsd_fh_hash()

[Chuck Lever]

Enable knfsd_fh_hash() to be invoked in functions where the
filehandle pointer is a const.

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 fs/nfsd/nfsfh.h |    7 ++-----
 1 file changed, 2 insertions(+), 5 deletions(-)

diff --git a/fs/nfsd/nfsfh.h b/fs/nfsd/nfsfh.h
index aff2cda5c6c3..6106697adc04 100644
--- a/fs/nfsd/nfsfh.h
+++ b/fs/nfsd/nfsfh.h
@@ -225,15 +225,12 @@ static inline bool fh_fsid_match(struct knfsd_fh *fh1, struct knfsd_fh *fh2)
  * returns a crc32 hash for the filehandle that is compatible with
  * the one displayed by "wireshark".
  */
-
-static inline u32
-knfsd_fh_hash(struct knfsd_fh *fh)
+static inline u32 knfsd_fh_hash(const struct knfsd_fh *fh)
 {
 	return ~crc32_le(0xFFFFFFFF, (unsigned char *)&fh->fh_base, fh->fh_size);
 }
 #else
-static inline u32
-knfsd_fh_hash(struct knfsd_fh *fh)
+static inline u32 knfsd_fh_hash(const struct knfsd_fh *fh)
 {
 	return 0;
 }

[PATCH v2 14/25] NFSD: Capture every CB state transition

[Chuck Lever]

We were missing one.

As a clean-up, add a helper that sets the new CB state and fires
a tracepoint. The tracepoint fires only when the state changes, to
help reduce trace log noise.

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 fs/nfsd/nfs4callback.c |   28 +++++++++++++++-------------
 1 file changed, 15 insertions(+), 13 deletions(-)

diff --git a/fs/nfsd/nfs4callback.c b/fs/nfsd/nfs4callback.c
index 7325592b456e..b6cc51a9f37c 100644
--- a/fs/nfsd/nfs4callback.c
+++ b/fs/nfsd/nfs4callback.c
@@ -945,20 +945,26 @@ static int setup_callback_client(struct nfs4_client *clp, struct nfs4_cb_conn *c
 	return 0;
 }
 
+static void nfsd4_mark_cb_state(struct nfs4_client *clp, int newstate)
+{
+	if (clp->cl_cb_state != newstate) {
+		clp->cl_cb_state = newstate;
+		trace_nfsd_cb_state(clp);
+	}
+}
+
 static void nfsd4_mark_cb_down(struct nfs4_client *clp, int reason)
 {
 	if (test_bit(NFSD4_CLIENT_CB_UPDATE, &clp->cl_flags))
 		return;
-	clp->cl_cb_state = NFSD4_CB_DOWN;
-	trace_nfsd_cb_state(clp);
+	nfsd4_mark_cb_state(clp, NFSD4_CB_DOWN);
 }
 
 static void nfsd4_mark_cb_fault(struct nfs4_client *clp, int reason)
 {
 	if (test_bit(NFSD4_CLIENT_CB_UPDATE, &clp->cl_flags))
 		return;
-	clp->cl_cb_state = NFSD4_CB_FAULT;
-	trace_nfsd_cb_state(clp);
+	nfsd4_mark_cb_state(clp, NFSD4_CB_FAULT);
 }
 
 static void nfsd4_cb_probe_done(struct rpc_task *task, void *calldata)
@@ -968,10 +974,8 @@ static void nfsd4_cb_probe_done(struct rpc_task *task, void *calldata)
 	trace_nfsd_cb_done(clp, task->tk_status);
 	if (task->tk_status)
 		nfsd4_mark_cb_down(clp, task->tk_status);
-	else {
-		clp->cl_cb_state = NFSD4_CB_UP;
-		trace_nfsd_cb_state(clp);
-	}
+	else
+		nfsd4_mark_cb_state(clp, NFSD4_CB_UP);
 }
 
 static void nfsd4_cb_probe_release(void *calldata)
@@ -995,8 +999,7 @@ static const struct rpc_call_ops nfsd4_cb_probe_ops = {
  */
 void nfsd4_probe_callback(struct nfs4_client *clp)
 {
-	clp->cl_cb_state = NFSD4_CB_UNKNOWN;
-	trace_nfsd_cb_state(clp);
+	nfsd4_mark_cb_state(clp, NFSD4_CB_UNKNOWN);
 	set_bit(NFSD4_CLIENT_CB_UPDATE, &clp->cl_flags);
 	nfsd4_run_cb(&clp->cl_cb_null);
 }
@@ -1009,11 +1012,10 @@ void nfsd4_probe_callback_sync(struct nfs4_client *clp)
 
 void nfsd4_change_callback(struct nfs4_client *clp, struct nfs4_cb_conn *conn)
 {
-	clp->cl_cb_state = NFSD4_CB_UNKNOWN;
+	nfsd4_mark_cb_state(clp, NFSD4_CB_UNKNOWN);
 	spin_lock(&clp->cl_lock);
 	memcpy(&clp->cl_cb_conn, conn, sizeof(struct nfs4_cb_conn));
 	spin_unlock(&clp->cl_lock);
-	trace_nfsd_cb_state(clp);
 }
 
 /*
@@ -1345,7 +1347,7 @@ nfsd4_run_cb_work(struct work_struct *work)
 	 * Don't send probe messages for 4.1 or later.
 	 */
 	if (!cb->cb_ops && clp->cl_minorversion) {
-		clp->cl_cb_state = NFSD4_CB_UP;
+		nfsd4_mark_cb_state(clp, NFSD4_CB_UP);
 		nfsd41_destroy_cb(cb);
 		return;
 	}

[PATCH v2 15/25] NFSD: Drop TRACE_DEFINE_ENUM for NFSD4_CB_<state> macros

[Chuck Lever]

TRACE_DEFINE_ENUM() is necessary for enum {} but not for C macros.

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 fs/nfsd/trace.h |    5 -----
 1 file changed, 5 deletions(-)

diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h
index 7de8ca581c5d..6afeda8652b3 100644
--- a/fs/nfsd/trace.h
+++ b/fs/nfsd/trace.h
@@ -874,11 +874,6 @@ TRACE_EVENT(nfsd_cb_nodelegs,
 	TP_printk("client %08x:%08x", __entry->cl_boot, __entry->cl_id)
 )
 
-TRACE_DEFINE_ENUM(NFSD4_CB_UP);
-TRACE_DEFINE_ENUM(NFSD4_CB_UNKNOWN);
-TRACE_DEFINE_ENUM(NFSD4_CB_DOWN);
-TRACE_DEFINE_ENUM(NFSD4_CB_FAULT);
-
 #define show_cb_state(val)						\
 	__print_symbolic(val,						\
 		{ NFSD4_CB_UP,		"UP" },				\

[PATCH v2 16/25] NFSD: Add cb_lost tracepoint

[Chuck Lever]

Provide more clarity about when the callback channel is in trouble.

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 fs/nfsd/nfs4state.c |    2 ++
 fs/nfsd/trace.h     |    1 +
 2 files changed, 3 insertions(+)

diff --git a/fs/nfsd/nfs4state.c b/fs/nfsd/nfs4state.c
index ad0139b6df15..79d504f461e6 100644
--- a/fs/nfsd/nfs4state.c
+++ b/fs/nfsd/nfs4state.c
@@ -1745,6 +1745,8 @@ static void nfsd4_conn_lost(struct svc_xpt_user *u)
 	struct nfsd4_conn *c = container_of(u, struct nfsd4_conn, cn_xpt_user);
 	struct nfs4_client *clp = c->cn_session->se_client;
 
+	trace_nfsd_cb_lost(clp);
+
 	spin_lock(&clp->cl_lock);
 	if (!list_empty(&c->cn_persession)) {
 		list_del(&c->cn_persession);
diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h
index 6afeda8652b3..bd683523b052 100644
--- a/fs/nfsd/trace.h
+++ b/fs/nfsd/trace.h
@@ -909,6 +909,7 @@ DEFINE_EVENT(nfsd_cb_class, nfsd_cb_##name,		\
 
 DEFINE_NFSD_CB_EVENT(setup);
 DEFINE_NFSD_CB_EVENT(state);
+DEFINE_NFSD_CB_EVENT(lost);
 DEFINE_NFSD_CB_EVENT(shutdown);
 
 TRACE_DEFINE_ENUM(RPC_AUTH_NULL);

[PATCH v2 17/25] NFSD: Adjust cb_shutdown tracepoint

[Chuck Lever]

Show when the upper layer requested a shutdown. RPC tracepoints can
already show when rpc_shutdown_client() is called.

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 fs/nfsd/nfs4callback.c |    4 +++-
 1 file changed, 3 insertions(+), 1 deletion(-)

diff --git a/fs/nfsd/nfs4callback.c b/fs/nfsd/nfs4callback.c
index b6cc51a9f37c..ab1836381e22 100644
--- a/fs/nfsd/nfs4callback.c
+++ b/fs/nfsd/nfs4callback.c
@@ -1233,6 +1233,9 @@ void nfsd4_destroy_callback_queue(void)
 /* must be called under the state lock */
 void nfsd4_shutdown_callback(struct nfs4_client *clp)
 {
+	if (clp->cl_cb_state != NFSD4_CB_UNKNOWN)
+		trace_nfsd_cb_shutdown(clp);
+
 	set_bit(NFSD4_CLIENT_CB_KILL, &clp->cl_flags);
 	/*
 	 * Note this won't actually result in a null callback;
@@ -1278,7 +1281,6 @@ static void nfsd4_process_cb_update(struct nfsd4_callback *cb)
 	 * kill the old client:
 	 */
 	if (clp->cl_cb_client) {
-		trace_nfsd_cb_shutdown(clp);
 		rpc_shutdown_client(clp->cl_cb_client);
 		clp->cl_cb_client = NULL;
 		put_cred(clp->cl_cb_cred);

[PATCH v2 18/25] NFSD: Remove spurious cb_setup_err tracepoint

[Chuck Lever]

This path is not really an error path, so the tracepoint I added
there is just noise.

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 fs/nfsd/nfs4callback.c |    4 +---
 1 file changed, 1 insertion(+), 3 deletions(-)

diff --git a/fs/nfsd/nfs4callback.c b/fs/nfsd/nfs4callback.c
index ab1836381e22..15ba16c54793 100644
--- a/fs/nfsd/nfs4callback.c
+++ b/fs/nfsd/nfs4callback.c
@@ -915,10 +915,8 @@ static int setup_callback_client(struct nfs4_client *clp, struct nfs4_cb_conn *c
 		args.authflavor = clp->cl_cred.cr_flavor;
 		clp->cl_cb_ident = conn->cb_ident;
 	} else {
-		if (!conn->cb_xprt) {
-			trace_nfsd_cb_setup_err(clp, -EINVAL);
+		if (!conn->cb_xprt)
 			return -EINVAL;
-		}
 		clp->cl_cb_conn.cb_xprt = conn->cb_xprt;
 		clp->cl_cb_session = ses;
 		args.bc_xprt = conn->cb_xprt;

[PATCH v2 19/25] NFSD: Enhance the nfsd_cb_setup tracepoint

[Chuck Lever]

Display the transport protocol and authentication flavor so admins
can see what they might be getting wrong.

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 fs/nfsd/nfs4callback.c |    3 ++-
 fs/nfsd/trace.h        |   27 ++++++++++++++++++++++++++-
 2 files changed, 28 insertions(+), 2 deletions(-)

diff --git a/fs/nfsd/nfs4callback.c b/fs/nfsd/nfs4callback.c
index 15ba16c54793..c2a2a58b3581 100644
--- a/fs/nfsd/nfs4callback.c
+++ b/fs/nfsd/nfs4callback.c
@@ -939,7 +939,8 @@ static int setup_callback_client(struct nfs4_client *clp, struct nfs4_cb_conn *c
 	}
 	clp->cl_cb_client = client;
 	clp->cl_cb_cred = cred;
-	trace_nfsd_cb_setup(clp);
+	trace_nfsd_cb_setup(clp, rpc_peeraddr2str(client, RPC_DISPLAY_NETID),
+			    args.authflavor);
 	return 0;
 }
 
diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h
index bd683523b052..a0d010d6e135 100644
--- a/fs/nfsd/trace.h
+++ b/fs/nfsd/trace.h
@@ -907,7 +907,6 @@ DEFINE_EVENT(nfsd_cb_class, nfsd_cb_##name,		\
 	TP_PROTO(const struct nfs4_client *clp),	\
 	TP_ARGS(clp))
 
-DEFINE_NFSD_CB_EVENT(setup);
 DEFINE_NFSD_CB_EVENT(state);
 DEFINE_NFSD_CB_EVENT(lost);
 DEFINE_NFSD_CB_EVENT(shutdown);
@@ -928,6 +927,32 @@ TRACE_DEFINE_ENUM(RPC_AUTH_GSS_KRB5P);
 		{ RPC_AUTH_GSS_KRB5I,		"krb5i" },		\
 		{ RPC_AUTH_GSS_KRB5P,		"krb5p" })
 
+TRACE_EVENT(nfsd_cb_setup,
+	TP_PROTO(const struct nfs4_client *clp,
+		 const char *netid,
+		 rpc_authflavor_t authflavor
+	),
+	TP_ARGS(clp, netid, authflavor),
+	TP_STRUCT__entry(
+		__field(u32, cl_boot)
+		__field(u32, cl_id)
+		__field(unsigned long, authflavor)
+		__array(unsigned char, addr, sizeof(struct sockaddr_in6))
+		__array(unsigned char, netid, 8)
+	),
+	TP_fast_assign(
+		__entry->cl_boot = clp->cl_clientid.cl_boot;
+		__entry->cl_id = clp->cl_clientid.cl_id;
+		strlcpy(__entry->netid, netid, sizeof(__entry->netid));
+		__entry->authflavor = authflavor;
+		memcpy(__entry->addr, &clp->cl_cb_conn.cb_addr,
+			sizeof(struct sockaddr_in6));
+	),
+	TP_printk("addr=%pISpc client %08x:%08x proto=%s flavor=%s",
+		__entry->addr, __entry->cl_boot, __entry->cl_id,
+		__entry->netid, show_nfsd_authflavor(__entry->authflavor))
+);
+
 TRACE_EVENT(nfsd_cb_setup_err,
 	TP_PROTO(
 		const struct nfs4_client *clp,

[PATCH v2 20/25] NFSD: Add an nfsd_cb_lm_notify tracepoint

[Chuck Lever]

When the server kicks off a CB_LM_NOTIFY callback, record its
arguments so we can better observe asynchronous locking behavior.
For example:

            nfsd-998   [002]  1471.705873: nfsd_cb_notify_lock:  addr=192.168.2.51:0 client 6092a47c:35a43fc1 fh_hash=0x8950b23a

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
Cc: Jeff Layton <jlayton@redhat.com>
---
 fs/nfsd/nfs4state.c |    4 +++-
 fs/nfsd/trace.h     |   26 ++++++++++++++++++++++++++
 2 files changed, 29 insertions(+), 1 deletion(-)

diff --git a/fs/nfsd/nfs4state.c b/fs/nfsd/nfs4state.c
index 79d504f461e6..2f2f38884c2c 100644
--- a/fs/nfsd/nfs4state.c
+++ b/fs/nfsd/nfs4state.c
@@ -6451,8 +6451,10 @@ nfsd4_lm_notify(struct file_lock *fl)
 	}
 	spin_unlock(&nn->blocked_locks_lock);
 
-	if (queue)
+	if (queue) {
+		trace_nfsd_cb_notify_lock(lo, nbl);
 		nfsd4_run_cb(&nbl->nbl_cb);
+	}
 }
 
 static const struct lock_manager_operations nfsd_posix_mng_ops  = {
diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h
index a0d010d6e135..9db47d0dd0d9 100644
--- a/fs/nfsd/trace.h
+++ b/fs/nfsd/trace.h
@@ -1024,6 +1024,32 @@ TRACE_EVENT(nfsd_cb_done,
 		__entry->status)
 );
 
+TRACE_EVENT(nfsd_cb_notify_lock,
+	TP_PROTO(
+		const struct nfs4_lockowner *lo,
+		const struct nfsd4_blocked_lock *nbl
+	),
+	TP_ARGS(lo, nbl),
+	TP_STRUCT__entry(
+		__field(u32, cl_boot)
+		__field(u32, cl_id)
+		__field(u32, fh_hash)
+		__array(unsigned char, addr, sizeof(struct sockaddr_in6))
+	),
+	TP_fast_assign(
+		const struct nfs4_client *clp = lo->lo_owner.so_client;
+
+		__entry->cl_boot = clp->cl_clientid.cl_boot;
+		__entry->cl_id = clp->cl_clientid.cl_id;
+		__entry->fh_hash = knfsd_fh_hash(&nbl->nbl_fh);
+		memcpy(__entry->addr, &clp->cl_cb_conn.cb_addr,
+			sizeof(struct sockaddr_in6));
+	),
+	TP_printk("addr=%pISpc client %08x:%08x fh_hash=0x%08x",
+		__entry->addr, __entry->cl_boot, __entry->cl_id,
+		__entry->fh_hash)
+);
+
 #endif /* _NFSD_TRACE_H */
 
 #undef TRACE_INCLUDE_PATH

[PATCH v2 21/25] NFSD: Add an nfsd_cb_offload tracepoint

[Chuck Lever]

Record the arguments of CB_OFFLOAD callbacks so we can better
observe asynchronous copy-offload behavior. For example:

            nfsd-995   [008]  7721.934222: nfsd_cb_offload:      addr=192.168.2.51:0 client 6092a47c:35a43fc1 fh_hash=0x8739113a

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
Cc: Olga Kornievskaia <kolga@netapp.com>
Cc: Dai Ngo <Dai.Ngo@oracle.com>
---
 fs/nfsd/nfs4proc.c |    1 +
 fs/nfsd/trace.h    |   30 ++++++++++++++++++++++++++++++
 2 files changed, 31 insertions(+)

diff --git a/fs/nfsd/nfs4proc.c b/fs/nfsd/nfs4proc.c
index f4ce93d7f26e..2ce7cb90a941 100644
--- a/fs/nfsd/nfs4proc.c
+++ b/fs/nfsd/nfs4proc.c
@@ -1497,6 +1497,7 @@ static int nfsd4_do_async_copy(void *data)
 	memcpy(&cb_copy->fh, &copy->fh, sizeof(copy->fh));
 	nfsd4_init_cb(&cb_copy->cp_cb, cb_copy->cp_clp,
 			&nfsd4_cb_offload_ops, NFSPROC4_CLNT_CB_OFFLOAD);
+	trace_nfsd_cb_offload(copy->cp_clp, &copy->cp_res.cb_stateid, &copy->fh);
 	nfsd4_run_cb(&cb_copy->cp_cb);
 out:
 	if (!copy->cp_intra)
diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h
index 9db47d0dd0d9..002623282e93 100644
--- a/fs/nfsd/trace.h
+++ b/fs/nfsd/trace.h
@@ -1050,6 +1050,36 @@ TRACE_EVENT(nfsd_cb_notify_lock,
 		__entry->fh_hash)
 );
 
+TRACE_EVENT(nfsd_cb_offload,
+	TP_PROTO(
+		const struct nfs4_client *clp,
+		const stateid_t *stp,
+		const struct knfsd_fh *fh
+	),
+	TP_ARGS(clp, stp, fh),
+	TP_STRUCT__entry(
+		__field(u32, cl_boot)
+		__field(u32, cl_id)
+		__field(u32, si_id)
+		__field(u32, si_generation)
+		__field(u32, fh_hash)
+		__array(unsigned char, addr, sizeof(struct sockaddr_in6))
+	),
+	TP_fast_assign(
+		__entry->cl_boot = stp->si_opaque.so_clid.cl_boot;
+		__entry->cl_id = stp->si_opaque.so_clid.cl_id;
+		__entry->si_id = stp->si_opaque.so_id;
+		__entry->si_generation = stp->si_generation;
+		__entry->fh_hash = knfsd_fh_hash(fh);
+		memcpy(__entry->addr, &clp->cl_cb_conn.cb_addr,
+			sizeof(struct sockaddr_in6));
+	),
+	TP_printk("addr=%pISpc client %08x:%08x stateid %08x:%08x fh_hash=0x%08x",
+		__entry->addr, __entry->cl_boot, __entry->cl_id,
+		__entry->si_id, __entry->si_generation,
+		__entry->fh_hash)
+);
+
 #endif /* _NFSD_TRACE_H */
 
 #undef TRACE_INCLUDE_PATH

[PATCH v2 22/25] NFSD: Replace the nfsd_deleg_break tracepoint

[Chuck Lever]

Renamed so it can be enabled as a set with the other nfsd_cb_
tracepoints. And, consistent with those tracepoints, report the
address of the client, the client ID the server has given it, and
the state ID being recalled.

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 fs/nfsd/nfs4state.c |    2 +-
 fs/nfsd/trace.h     |   32 +++++++++++++++++++++++++++++++-
 2 files changed, 32 insertions(+), 2 deletions(-)

diff --git a/fs/nfsd/nfs4state.c b/fs/nfsd/nfs4state.c
index 2f2f38884c2c..49c052243b5c 100644
--- a/fs/nfsd/nfs4state.c
+++ b/fs/nfsd/nfs4state.c
@@ -4639,7 +4639,7 @@ nfsd_break_deleg_cb(struct file_lock *fl)
 	struct nfs4_delegation *dp = (struct nfs4_delegation *)fl->fl_owner;
 	struct nfs4_file *fp = dp->dl_stid.sc_file;
 
-	trace_nfsd_deleg_break(&dp->dl_stid.sc_stateid);
+	trace_nfsd_cb_recall(&dp->dl_stid);
 
 	/*
 	 * We don't want the locks code to timeout the lease for us;
diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h
index 002623282e93..7f6a2cae0019 100644
--- a/fs/nfsd/trace.h
+++ b/fs/nfsd/trace.h
@@ -457,7 +457,6 @@ DEFINE_STATEID_EVENT(layout_recall_release);
 
 DEFINE_STATEID_EVENT(open);
 DEFINE_STATEID_EVENT(deleg_read);
-DEFINE_STATEID_EVENT(deleg_break);
 DEFINE_STATEID_EVENT(deleg_recall);
 
 DECLARE_EVENT_CLASS(nfsd_stateseqid_class,
@@ -1024,6 +1023,37 @@ TRACE_EVENT(nfsd_cb_done,
 		__entry->status)
 );
 
+TRACE_EVENT(nfsd_cb_recall,
+	TP_PROTO(
+		const struct nfs4_stid *stid
+	),
+	TP_ARGS(stid),
+	TP_STRUCT__entry(
+		__field(u32, cl_boot)
+		__field(u32, cl_id)
+		__field(u32, si_id)
+		__field(u32, si_generation)
+		__array(unsigned char, addr, sizeof(struct sockaddr_in6))
+	),
+	TP_fast_assign(
+		const stateid_t *stp = &stid->sc_stateid;
+		const struct nfs4_client *clp = stid->sc_client;
+
+		__entry->cl_boot = stp->si_opaque.so_clid.cl_boot;
+		__entry->cl_id = stp->si_opaque.so_clid.cl_id;
+		__entry->si_id = stp->si_opaque.so_id;
+		__entry->si_generation = stp->si_generation;
+		if (clp)
+			memcpy(__entry->addr, &clp->cl_cb_conn.cb_addr,
+				sizeof(struct sockaddr_in6));
+		else
+			memset(__entry->addr, 0, sizeof(struct sockaddr_in6));
+	),
+	TP_printk("addr=%pISpc client %08x:%08x stateid %08x:%08x",
+		__entry->addr, __entry->cl_boot, __entry->cl_id,
+		__entry->si_id, __entry->si_generation)
+);
+
 TRACE_EVENT(nfsd_cb_notify_lock,
 	TP_PROTO(
 		const struct nfs4_lockowner *lo,

[PATCH v2 23/25] NFSD: Add an nfsd_cb_probe tracepoint

[Chuck Lever]

Record a tracepoint event when the server performs a callback
probe. This event can be enabled as a group with other nfsd_cb
tracepoints.

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 fs/nfsd/nfs4callback.c |    1 +
 fs/nfsd/trace.h        |    1 +
 2 files changed, 2 insertions(+)

diff --git a/fs/nfsd/nfs4callback.c b/fs/nfsd/nfs4callback.c
index c2a2a58b3581..ddab969d7865 100644
--- a/fs/nfsd/nfs4callback.c
+++ b/fs/nfsd/nfs4callback.c
@@ -998,6 +998,7 @@ static const struct rpc_call_ops nfsd4_cb_probe_ops = {
  */
 void nfsd4_probe_callback(struct nfs4_client *clp)
 {
+	trace_nfsd_cb_probe(clp);
 	nfsd4_mark_cb_state(clp, NFSD4_CB_UNKNOWN);
 	set_bit(NFSD4_CLIENT_CB_UPDATE, &clp->cl_flags);
 	nfsd4_run_cb(&clp->cl_cb_null);
diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h
index 7f6a2cae0019..da8e7a5a9c61 100644
--- a/fs/nfsd/trace.h
+++ b/fs/nfsd/trace.h
@@ -907,6 +907,7 @@ DEFINE_EVENT(nfsd_cb_class, nfsd_cb_##name,		\
 	TP_ARGS(clp))
 
 DEFINE_NFSD_CB_EVENT(state);
+DEFINE_NFSD_CB_EVENT(probe);
 DEFINE_NFSD_CB_EVENT(lost);
 DEFINE_NFSD_CB_EVENT(shutdown);
 

[PATCH v2 24/25] NFSD: Remove the nfsd_cb_work and nfsd_cb_done tracepoints

[Chuck Lever]

Clean up: These are noise in properly working systems. If you really
need to observe the operation of the callback mechanism, use the
sunrpc:rpc\* tracepoints along with the workqueue tracepoints.

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 fs/nfsd/nfs4callback.c |    5 -----
 fs/nfsd/trace.h        |   48 ------------------------------------------------
 2 files changed, 53 deletions(-)

diff --git a/fs/nfsd/nfs4callback.c b/fs/nfsd/nfs4callback.c
index ddab969d7865..84401ca04705 100644
--- a/fs/nfsd/nfs4callback.c
+++ b/fs/nfsd/nfs4callback.c
@@ -970,7 +970,6 @@ static void nfsd4_cb_probe_done(struct rpc_task *task, void *calldata)
 {
 	struct nfs4_client *clp = container_of(calldata, struct nfs4_client, cl_cb_null);
 
-	trace_nfsd_cb_done(clp, task->tk_status);
 	if (task->tk_status)
 		nfsd4_mark_cb_down(clp, task->tk_status);
 	else
@@ -1172,8 +1171,6 @@ static void nfsd4_cb_done(struct rpc_task *task, void *calldata)
 	struct nfsd4_callback *cb = calldata;
 	struct nfs4_client *clp = cb->cb_clp;
 
-	trace_nfsd_cb_done(clp, task->tk_status);
-
 	if (!nfsd4_cb_sequence_done(task, cb))
 		return;
 
@@ -1326,8 +1323,6 @@ nfsd4_run_cb_work(struct work_struct *work)
 	struct rpc_clnt *clnt;
 	int flags;
 
-	trace_nfsd_cb_work(clp, cb->cb_msg.rpc_proc->p_name);
-
 	if (cb->cb_need_restart) {
 		cb->cb_need_restart = false;
 	} else {
diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h
index da8e7a5a9c61..4b916fb4a388 100644
--- a/fs/nfsd/trace.h
+++ b/fs/nfsd/trace.h
@@ -976,54 +976,6 @@ TRACE_EVENT(nfsd_cb_setup_err,
 		__entry->addr, __entry->cl_boot, __entry->cl_id, __entry->error)
 );
 
-TRACE_EVENT(nfsd_cb_work,
-	TP_PROTO(
-		const struct nfs4_client *clp,
-		const char *procedure
-	),
-	TP_ARGS(clp, procedure),
-	TP_STRUCT__entry(
-		__field(u32, cl_boot)
-		__field(u32, cl_id)
-		__string(procedure, procedure)
-		__array(unsigned char, addr, sizeof(struct sockaddr_in6))
-	),
-	TP_fast_assign(
-		__entry->cl_boot = clp->cl_clientid.cl_boot;
-		__entry->cl_id = clp->cl_clientid.cl_id;
-		__assign_str(procedure, procedure)
-		memcpy(__entry->addr, &clp->cl_cb_conn.cb_addr,
-			sizeof(struct sockaddr_in6));
-	),
-	TP_printk("addr=%pISpc client %08x:%08x procedure=%s",
-		__entry->addr, __entry->cl_boot, __entry->cl_id,
-		__get_str(procedure))
-);
-
-TRACE_EVENT(nfsd_cb_done,
-	TP_PROTO(
-		const struct nfs4_client *clp,
-		int status
-	),
-	TP_ARGS(clp, status),
-	TP_STRUCT__entry(
-		__field(u32, cl_boot)
-		__field(u32, cl_id)
-		__field(int, status)
-		__array(unsigned char, addr, sizeof(struct sockaddr_in6))
-	),
-	TP_fast_assign(
-		__entry->cl_boot = clp->cl_clientid.cl_boot;
-		__entry->cl_id = clp->cl_clientid.cl_id;
-		__entry->status = status;
-		memcpy(__entry->addr, &clp->cl_cb_conn.cb_addr,
-			sizeof(struct sockaddr_in6));
-	),
-	TP_printk("addr=%pISpc client %08x:%08x status=%d",
-		__entry->addr, __entry->cl_boot, __entry->cl_id,
-		__entry->status)
-);
-
 TRACE_EVENT(nfsd_cb_recall,
 	TP_PROTO(
 		const struct nfs4_stid *stid

[PATCH v2 25/25] NFSD: Update nfsd_cb_args tracepoint

[Chuck Lever]

Clean-up: Re-order the display of IP address and client ID to be
consistent with other _cb_ tracepoints.

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 fs/nfsd/trace.h |    6 +++---
 1 file changed, 3 insertions(+), 3 deletions(-)

diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h
index 4b916fb4a388..eba5b51a08e7 100644
--- a/fs/nfsd/trace.h
+++ b/fs/nfsd/trace.h
@@ -854,9 +854,9 @@ TRACE_EVENT(nfsd_cb_args,
 		memcpy(__entry->addr, &conn->cb_addr,
 			sizeof(struct sockaddr_in6));
 	),
-	TP_printk("client %08x:%08x callback addr=%pISpc prog=%u ident=%u",
-		__entry->cl_boot, __entry->cl_id,
-		__entry->addr, __entry->prog, __entry->ident)
+	TP_printk("addr=%pISpc client %08x:%08x prog=%u ident=%u",
+		__entry->addr, __entry->cl_boot, __entry->cl_id,
+		__entry->prog, __entry->ident)
 );
 
 TRACE_EVENT(nfsd_cb_nodelegs,

Re: [PATCH v2 01/25] NFSD: Fix TP_printk() format specifier in trace_nfsd_dirent()

[Steven Rostedt]

On Wed, 12 May 2021 11:35:02 -0400
Chuck Lever <chuck.lever@oracle.com> wrote:

> Since commit 9a6944fee68e ("tracing: Add a verifier to check string
> pointers for trace events"), which was merged in v5.13-rc1,
> TP_printk() no longer tacitly supports the "%.*s" format specifier.

Hmm, this looks like a bug. I should allow the %.*s notation.

I probably should fix that.

-- Steve

Re: [PATCH v2 01/25] NFSD: Fix TP_printk() format specifier in trace_nfsd_dirent()

[Chuck Lever III]

Hi Steve-

> On May 12, 2021, at 12:26 PM, Steven Rostedt <rostedt@goodmis.org> wrote:
> 
> On Wed, 12 May 2021 11:35:02 -0400
> Chuck Lever <chuck.lever@oracle.com> wrote:
> 
>> Since commit 9a6944fee68e ("tracing: Add a verifier to check string
>> pointers for trace events"), which was merged in v5.13-rc1,
>> TP_printk() no longer tacitly supports the "%.*s" format specifier.
> 
> Hmm, this looks like a bug. I should allow the %.*s notation.
> 
> I probably should fix that.

The underlying need is to support non-NUL-terminated C strings.

I assumed that since the commentary around 9a6944fee68e claims
the proper way to trace C strings is to use __string and friends,
and those do not support non-NUL-terminated strings, that such
strings are really not first-class citizens. Thus I concluded
that my use of '%.*s' was incorrect.

Having some __string-style helpers that can deal with such
strings would be valuable.


--
Chuck Lever

Re: [PATCH v2 01/25] NFSD: Fix TP_printk() format specifier in trace_nfsd_dirent()

[Steven Rostedt]

On Wed, 12 May 2021 12:26:23 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> On Wed, 12 May 2021 11:35:02 -0400
> Chuck Lever <chuck.lever@oracle.com> wrote:
> 
> > Since commit 9a6944fee68e ("tracing: Add a verifier to check string
> > pointers for trace events"), which was merged in v5.13-rc1,
> > TP_printk() no longer tacitly supports the "%.*s" format specifier.  
> 
> Hmm, this looks like a bug. I should allow the %.*s notation.
> 
> I probably should fix that.

Only compiled tested, but the %.*s notation should work with this.

-- Steve

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index e28d08905124..0181122f1e80 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -3700,6 +3700,9 @@ void trace_check_vprintf(struct trace_iterator *iter, const char *fmt,
 		goto print;
 
 	while (*p) {
+		bool star = false;
+		int len = 0;
+
 		j = 0;
 
 		/* We only care about %s and variants */
@@ -3721,13 +3724,17 @@ void trace_check_vprintf(struct trace_iterator *iter, const char *fmt,
 				/* Need to test cases like %08.*s */
 				for (j = 1; p[i+j]; j++) {
 					if (isdigit(p[i+j]) ||
-					    p[i+j] == '*' ||
 					    p[i+j] == '.')
 						continue;
+					if (p[i+j] == '*') {
+						star = true;
+						continue;
+					}
 					break;
 				}
 				if (p[i+j] == 's')
 					break;
+				star = false;
 			}
 			j = 0;
 		}
@@ -3740,6 +3747,9 @@ void trace_check_vprintf(struct trace_iterator *iter, const char *fmt,
 		iter->fmt[i] = '\0';
 		trace_seq_vprintf(&iter->seq, iter->fmt, ap);
 
+		if (star)
+			len = va_arg(ap, int);
+
 		/* The ap now points to the string data of the %s */
 		str = va_arg(ap, const char *);
 
@@ -3758,8 +3768,18 @@ void trace_check_vprintf(struct trace_iterator *iter, const char *fmt,
 			int ret;
 
 			/* Try to safely read the string */
-			ret = strncpy_from_kernel_nofault(iter->fmt, str,
-							  iter->fmt_size);
+			if (star) {
+				if (len + 1 > iter->fmt_size)
+					len = iter->fmt_size - 1;
+				if (len < 0)
+					len = 0;
+				ret = copy_from_kernel_nofault(iter->fmt, str, len);
+				iter->fmt[len] = 0;
+				star = false;
+			} else {
+				ret = strncpy_from_kernel_nofault(iter->fmt, str,
+								  iter->fmt_size);
+			}
 			if (ret < 0)
 				trace_seq_printf(&iter->seq, "(0x%px)", str);
 			else
@@ -3771,7 +3791,10 @@ void trace_check_vprintf(struct trace_iterator *iter, const char *fmt,
 			strncpy(iter->fmt, p + i, j + 1);
 			iter->fmt[j+1] = '\0';
 		}
-		trace_seq_printf(&iter->seq, iter->fmt, str);
+		if (star)
+			trace_seq_printf(&iter->seq, iter->fmt, len, str);
+		else
+			trace_seq_printf(&iter->seq, iter->fmt, str);
 
 		p += i + j + 1;
 	}

Re: [PATCH v2 01/25] NFSD: Fix TP_printk() format specifier in trace_nfsd_dirent()

[Steven Rostedt]

On Wed, 12 May 2021 16:52:05 +0000
Chuck Lever III <chuck.lever@oracle.com> wrote:

> The underlying need is to support non-NUL-terminated C strings.
> 
> I assumed that since the commentary around 9a6944fee68e claims
> the proper way to trace C strings is to use __string and friends,
> and those do not support non-NUL-terminated strings, that such
> strings are really not first-class citizens. Thus I concluded
> that my use of '%.*s' was incorrect.
> 
> Having some __string-style helpers that can deal with such
> strings would be valuable.

I guess the best I can do is a strncpy version, that will add the '\0' in
the ring buffer. That way we don't need to save the length as well (length
would need to be at least 4 bytes, where as '\0' is one).

Something like this?

I added "__string_len()" and "__assign_str_len()". You use them just like
__string() and __assign_str() but add a max length that you want to use
(although, it will always allocate "len" regardless if the string is
smaller). Then use __get_str() just like you use __string().

Would something like that work?

-- Steve

diff --git a/include/trace/trace_events.h b/include/trace/trace_events.h
index 8268bf747d6f..7ab23535a0c8 100644
--- a/include/trace/trace_events.h
+++ b/include/trace/trace_events.h
@@ -102,6 +102,9 @@ TRACE_MAKE_SYSTEM_STR();
 #undef __string
 #define __string(item, src) __dynamic_array(char, item, -1)
 
+#undef __string_len
+#define __string_len(item, src, len) __dynamic_array(char, item, -1)
+
 #undef __bitmask
 #define __bitmask(item, nr_bits) __dynamic_array(char, item, -1)
 
@@ -197,6 +200,9 @@ TRACE_MAKE_SYSTEM_STR();
 #undef __string
 #define __string(item, src) __dynamic_array(char, item, -1)
 
+#undef __string_len
+#define __string_len(item, src, len) __dynamic_array(char, item, -1)
+
 #undef __bitmask
 #define __bitmask(item, nr_bits) __dynamic_array(unsigned long, item, -1)
 
@@ -444,6 +450,9 @@ static struct trace_event_functions trace_event_type_funcs_##call = {	\
 #undef __string
 #define __string(item, src) __dynamic_array(char, item, -1)
 
+#undef __string_len
+#define __string_len(item, src, len) __dynamic_array(char, item, -1)
+
 #undef __bitmask
 #define __bitmask(item, nr_bits) __dynamic_array(unsigned long, item, -1)
 
@@ -492,6 +501,9 @@ static struct trace_event_fields trace_event_fields_##call[] = {	\
 #define __string(item, src) __dynamic_array(char, item,			\
 		    strlen((src) ? (const char *)(src) : "(null)") + 1)
 
+#undef __string_len
+#define __string_len(item, src, len) __dynamic_array(char, item, (len) + 1)
+
 /*
  * __bitmask_size_in_bytes_raw is the number of bytes needed to hold
  * num_possible_cpus().
@@ -655,10 +667,18 @@ static inline notrace int trace_event_get_offsets_##call(		\
 #undef __string
 #define __string(item, src) __dynamic_array(char, item, -1)
 
+#undef __string_len
+#define __string_len(item, src, len) __dynamic_array(char, item, -1)
+
 #undef __assign_str
 #define __assign_str(dst, src)						\
 	strcpy(__get_str(dst), (src) ? (const char *)(src) : "(null)");
 
+#undef __assign_str_len
+#define __assign_str_len(dst, src, len)						\
+	strncpy(__get_str(dst), (src) ? (const char *)(src) : "(null)", len);	\
+	__get_str(dst)[len] = '\0';
+
 #undef __bitmask
 #define __bitmask(item, nr_bits) __dynamic_array(unsigned long, item, -1)
 

Re: [PATCH v2 01/25] NFSD: Fix TP_printk() format specifier in trace_nfsd_dirent()

[Chuck Lever III]

> On May 13, 2021, at 10:50 AM, Steven Rostedt <rostedt@goodmis.org> wrote:
> 
> On Wed, 12 May 2021 16:52:05 +0000
> Chuck Lever III <chuck.lever@oracle.com> wrote:
> 
>> The underlying need is to support non-NUL-terminated C strings.
>> 
>> I assumed that since the commentary around 9a6944fee68e claims
>> the proper way to trace C strings is to use __string and friends,
>> and those do not support non-NUL-terminated strings, that such
>> strings are really not first-class citizens. Thus I concluded
>> that my use of '%.*s' was incorrect.
>> 
>> Having some __string-style helpers that can deal with such
>> strings would be valuable.
> 
> I guess the best I can do is a strncpy version, that will add the '\0' in
> the ring buffer. That way we don't need to save the length as well (length
> would need to be at least 4 bytes, where as '\0' is one).
> 
> Something like this?

That looks about right!

With the caveat that a non-NUL-terminated string might contain a NUL.
When displayed with '%s', such a string would be truncated.


> I added "__string_len()" and "__assign_str_len()". You use them just like
> __string() and __assign_str() but add a max length that you want to use
> (although, it will always allocate "len" regardless if the string is
> smaller). Then use __get_str() just like you use __string().
> 
> Would something like that work?
> 
> -- Steve
> 
> diff --git a/include/trace/trace_events.h b/include/trace/trace_events.h
> index 8268bf747d6f..7ab23535a0c8 100644
> --- a/include/trace/trace_events.h
> +++ b/include/trace/trace_events.h
> @@ -102,6 +102,9 @@ TRACE_MAKE_SYSTEM_STR();
> #undef __string
> #define __string(item, src) __dynamic_array(char, item, -1)
> 
> +#undef __string_len
> +#define __string_len(item, src, len) __dynamic_array(char, item, -1)
> +
> #undef __bitmask
> #define __bitmask(item, nr_bits) __dynamic_array(char, item, -1)
> 
> @@ -197,6 +200,9 @@ TRACE_MAKE_SYSTEM_STR();
> #undef __string
> #define __string(item, src) __dynamic_array(char, item, -1)
> 
> +#undef __string_len
> +#define __string_len(item, src, len) __dynamic_array(char, item, -1)
> +
> #undef __bitmask
> #define __bitmask(item, nr_bits) __dynamic_array(unsigned long, item, -1)
> 
> @@ -444,6 +450,9 @@ static struct trace_event_functions trace_event_type_funcs_##call = {	\
> #undef __string
> #define __string(item, src) __dynamic_array(char, item, -1)
> 
> +#undef __string_len
> +#define __string_len(item, src, len) __dynamic_array(char, item, -1)
> +
> #undef __bitmask
> #define __bitmask(item, nr_bits) __dynamic_array(unsigned long, item, -1)
> 
> @@ -492,6 +501,9 @@ static struct trace_event_fields trace_event_fields_##call[] = {	\
> #define __string(item, src) __dynamic_array(char, item,			\
> 		    strlen((src) ? (const char *)(src) : "(null)") + 1)
> 
> +#undef __string_len
> +#define __string_len(item, src, len) __dynamic_array(char, item, (len) + 1)
> +
> /*
>  * __bitmask_size_in_bytes_raw is the number of bytes needed to hold
>  * num_possible_cpus().
> @@ -655,10 +667,18 @@ static inline notrace int trace_event_get_offsets_##call(		\
> #undef __string
> #define __string(item, src) __dynamic_array(char, item, -1)
> 
> +#undef __string_len
> +#define __string_len(item, src, len) __dynamic_array(char, item, -1)
> +
> #undef __assign_str
> #define __assign_str(dst, src)						\
> 	strcpy(__get_str(dst), (src) ? (const char *)(src) : "(null)");
> 
> +#undef __assign_str_len
> +#define __assign_str_len(dst, src, len)						\
> +	strncpy(__get_str(dst), (src) ? (const char *)(src) : "(null)", len);	\
> +	__get_str(dst)[len] = '\0';
> +
> #undef __bitmask
> #define __bitmask(item, nr_bits) __dynamic_array(unsigned long, item, -1)
> 
> 
> 

--
Chuck Lever

Re: [PATCH v2 01/25] NFSD: Fix TP_printk() format specifier in trace_nfsd_dirent()

[Steven Rostedt]

On Thu, 13 May 2021 14:53:35 +0000
Chuck Lever III <chuck.lever@oracle.com> wrote:

> > Something like this?  
> 
> That looks about right!
> 
> With the caveat that a non-NUL-terminated string might contain a NUL.
> When displayed with '%s', such a string would be truncated.

Right, but that would be the case even with %.*s. So it works the same.

-- Steve

Re: [PATCH v2 01/25] NFSD: Fix TP_printk() format specifier in trace_nfsd_dirent()

[Chuck Lever III]

> On May 13, 2021, at 10:50 AM, Steven Rostedt <rostedt@goodmis.org> wrote:
> 
> On Wed, 12 May 2021 16:52:05 +0000
> Chuck Lever III <chuck.lever@oracle.com> wrote:
> 
>> The underlying need is to support non-NUL-terminated C strings.
>> 
>> I assumed that since the commentary around 9a6944fee68e claims
>> the proper way to trace C strings is to use __string and friends,
>> and those do not support non-NUL-terminated strings, that such
>> strings are really not first-class citizens. Thus I concluded
>> that my use of '%.*s' was incorrect.
>> 
>> Having some __string-style helpers that can deal with such
>> strings would be valuable.
> 
> I guess the best I can do is a strncpy version, that will add the '\0' in
> the ring buffer. That way we don't need to save the length as well (length
> would need to be at least 4 bytes, where as '\0' is one).
> 
> Something like this?
> 
> I added "__string_len()" and "__assign_str_len()". You use them just like
> __string() and __assign_str() but add a max length that you want to use
> (although, it will always allocate "len" regardless if the string is
> smaller). Then use __get_str() just like you use __string().
> 
> Would something like that work?

I will test later today and let you know in this thread.


> -- Steve
> 
> diff --git a/include/trace/trace_events.h b/include/trace/trace_events.h
> index 8268bf747d6f..7ab23535a0c8 100644
> --- a/include/trace/trace_events.h
> +++ b/include/trace/trace_events.h
> @@ -102,6 +102,9 @@ TRACE_MAKE_SYSTEM_STR();
> #undef __string
> #define __string(item, src) __dynamic_array(char, item, -1)
> 
> +#undef __string_len
> +#define __string_len(item, src, len) __dynamic_array(char, item, -1)
> +
> #undef __bitmask
> #define __bitmask(item, nr_bits) __dynamic_array(char, item, -1)
> 
> @@ -197,6 +200,9 @@ TRACE_MAKE_SYSTEM_STR();
> #undef __string
> #define __string(item, src) __dynamic_array(char, item, -1)
> 
> +#undef __string_len
> +#define __string_len(item, src, len) __dynamic_array(char, item, -1)
> +
> #undef __bitmask
> #define __bitmask(item, nr_bits) __dynamic_array(unsigned long, item, -1)
> 
> @@ -444,6 +450,9 @@ static struct trace_event_functions trace_event_type_funcs_##call = {	\
> #undef __string
> #define __string(item, src) __dynamic_array(char, item, -1)
> 
> +#undef __string_len
> +#define __string_len(item, src, len) __dynamic_array(char, item, -1)
> +
> #undef __bitmask
> #define __bitmask(item, nr_bits) __dynamic_array(unsigned long, item, -1)
> 
> @@ -492,6 +501,9 @@ static struct trace_event_fields trace_event_fields_##call[] = {	\
> #define __string(item, src) __dynamic_array(char, item,			\
> 		    strlen((src) ? (const char *)(src) : "(null)") + 1)
> 
> +#undef __string_len
> +#define __string_len(item, src, len) __dynamic_array(char, item, (len) + 1)
> +
> /*
>  * __bitmask_size_in_bytes_raw is the number of bytes needed to hold
>  * num_possible_cpus().
> @@ -655,10 +667,18 @@ static inline notrace int trace_event_get_offsets_##call(		\
> #undef __string
> #define __string(item, src) __dynamic_array(char, item, -1)
> 
> +#undef __string_len
> +#define __string_len(item, src, len) __dynamic_array(char, item, -1)
> +
> #undef __assign_str
> #define __assign_str(dst, src)						\
> 	strcpy(__get_str(dst), (src) ? (const char *)(src) : "(null)");
> 
> +#undef __assign_str_len
> +#define __assign_str_len(dst, src, len)						\
> +	strncpy(__get_str(dst), (src) ? (const char *)(src) : "(null)", len);	\
> +	__get_str(dst)[len] = '\0';
> +
> #undef __bitmask
> #define __bitmask(item, nr_bits) __dynamic_array(unsigned long, item, -1)
> 
> 
> 

--
Chuck Lever

Re: [PATCH v2 09/25] NFSD: Add a couple more nfsd_clid_expired call sites

[David Wysochanski]

On Wed, May 12, 2021 at 11:36 AM Chuck Lever <chuck.lever@oracle.com> wrote:
>
> Improve observation of NFSv4 lease expiry.
>
> Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
> ---
>  fs/nfsd/nfs4state.c |    3 +++
>  1 file changed, 3 insertions(+)
>

How about adding a parameter to explain the location of the expiry to
make it more slightly more readable?
Below is an attempt at the two added here, I think there's one more
not shown though in nfs4_laundromat, which you could just use
"laundromat".

> diff --git a/fs/nfsd/nfs4state.c b/fs/nfsd/nfs4state.c
> index 08ff643e96fb..7fa90a3177fa 100644
> --- a/fs/nfsd/nfs4state.c
> +++ b/fs/nfsd/nfs4state.c
> @@ -2665,6 +2665,8 @@ static void force_expire_client(struct nfs4_client *clp)
>         struct nfsd_net *nn = net_generic(clp->net, nfsd_net_id);
>         bool already_expired;
>
> +       trace_nfsd_clid_expired(&clp->cl_clientid);
> +

trace_nfsd_clid_expired(..., "admin forced");

>         spin_lock(&clp->cl_lock);
>         clp->cl_time = 0;
>         spin_unlock(&clp->cl_lock);
> @@ -4075,6 +4077,7 @@ nfsd4_setclientid_confirm(struct svc_rqst *rqstp,
>                                 goto out;
>                         status = mark_client_expired_locked(old);
>                         if (status) {
> +                               trace_nfsd_clid_expired(&old->cl_clientid);

trace_nfsd_clid_expired(..., "setclientid_confirm existing"); /* found
an existing confirmed clientid by name */

>                                 old = NULL;
>                                 goto out;
>                         }
>
>

Re: [PATCH v2 09/25] NFSD: Add a couple more nfsd_clid_expired call sites

[Chuck Lever III]

> On May 13, 2021, at 12:42 PM, David Wysochanski <dwysocha@redhat.com> wrote:
> 
> On Wed, May 12, 2021 at 11:36 AM Chuck Lever <chuck.lever@oracle.com> wrote:
>> 
>> Improve observation of NFSv4 lease expiry.
>> 
>> Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
>> ---
>> fs/nfsd/nfs4state.c |    3 +++
>> 1 file changed, 3 insertions(+)
>> 
> 
> How about adding a parameter to explain the location of the expiry to
> make it more slightly more readable?
> Below is an attempt at the two added here, I think there's one more
> not shown though in nfs4_laundromat, which you could just use
> "laundromat".

The usual idiom is to create a trace class, and then create a uniquely
named tracepoint for each call site. We already have nfsd_clientid_class
so half the work is already done! I'll look into it splitting
clid_expired into several tracecpoints.


>> diff --git a/fs/nfsd/nfs4state.c b/fs/nfsd/nfs4state.c
>> index 08ff643e96fb..7fa90a3177fa 100644
>> --- a/fs/nfsd/nfs4state.c
>> +++ b/fs/nfsd/nfs4state.c
>> @@ -2665,6 +2665,8 @@ static void force_expire_client(struct nfs4_client *clp)
>>        struct nfsd_net *nn = net_generic(clp->net, nfsd_net_id);
>>        bool already_expired;
>> 
>> +       trace_nfsd_clid_expired(&clp->cl_clientid);
>> +
> 
> trace_nfsd_clid_expired(..., "admin forced");
> 
>>        spin_lock(&clp->cl_lock);
>>        clp->cl_time = 0;
>>        spin_unlock(&clp->cl_lock);
>> @@ -4075,6 +4077,7 @@ nfsd4_setclientid_confirm(struct svc_rqst *rqstp,
>>                                goto out;
>>                        status = mark_client_expired_locked(old);
>>                        if (status) {
>> +                               trace_nfsd_clid_expired(&old->cl_clientid);
> 
> trace_nfsd_clid_expired(..., "setclientid_confirm existing"); /* found
> an existing confirmed clientid by name */
> 
>>                                old = NULL;
>>                                goto out;
>>                        }
>> 
>> 
> 

--
Chuck Lever

Re: [PATCH v2 01/25] NFSD: Fix TP_printk() format specifier in trace_nfsd_dirent()

[Chuck Lever III]

> On May 13, 2021, at 11:10 AM, Chuck Lever III <chuck.lever@oracle.com> wrote:
> 
>> On May 13, 2021, at 10:50 AM, Steven Rostedt <rostedt@goodmis.org> wrote:
>> 
>> On Wed, 12 May 2021 16:52:05 +0000
>> Chuck Lever III <chuck.lever@oracle.com> wrote:
>> 
>>> The underlying need is to support non-NUL-terminated C strings.
>>> 
>>> I assumed that since the commentary around 9a6944fee68e claims
>>> the proper way to trace C strings is to use __string and friends,
>>> and those do not support non-NUL-terminated strings, that such
>>> strings are really not first-class citizens. Thus I concluded
>>> that my use of '%.*s' was incorrect.
>>> 
>>> Having some __string-style helpers that can deal with such
>>> strings would be valuable.
>> 
>> I guess the best I can do is a strncpy version, that will add the '\0' in
>> the ring buffer. That way we don't need to save the length as well (length
>> would need to be at least 4 bytes, where as '\0' is one).
>> 
>> Something like this?
>> 
>> I added "__string_len()" and "__assign_str_len()". You use them just like
>> __string() and __assign_str() but add a max length that you want to use
>> (although, it will always allocate "len" regardless if the string is
>> smaller). Then use __get_str() just like you use __string().
>> 
>> Would something like that work?
> 
> I will test later today and let you know in this thread.

All good.

Tested-by: Chuck Lever <chuck.lever@oracle.com>


--
Chuck Lever

Re: [PATCH v2 01/25] NFSD: Fix TP_printk() format specifier in trace_nfsd_dirent()

[Steven Rostedt]

On Thu, 13 May 2021 18:43:29 +0000
Chuck Lever III <chuck.lever@oracle.com> wrote:

> >> Would something like that work?  
> > 
> > I will test later today and let you know in this thread.  
> 
> All good.
> 
> Tested-by: Chuck Lever <chuck.lever@oracle.com>

Thanks, since this is an enhancement and not a fix, it will need to wait
till the next merge window to go in.

I can write up a formal patch and let you add it to this patch set as the
first patch, or I can add it to my tree if you don't expect this to get
into the next merge window.

-- Steve

Re: [PATCH v2 01/25] NFSD: Fix TP_printk() format specifier in trace_nfsd_dirent()

[Chuck Lever III]

> On May 13, 2021, at 3:00 PM, Steven Rostedt <rostedt@goodmis.org> wrote:
> 
> On Thu, 13 May 2021 18:43:29 +0000
> Chuck Lever III <chuck.lever@oracle.com> wrote:
> 
>>>> Would something like that work?  
>>> 
>>> I will test later today and let you know in this thread.  
>> 
>> All good.
>> 
>> Tested-by: Chuck Lever <chuck.lever@oracle.com>
> 
> Thanks, since this is an enhancement and not a fix, it will need to wait
> till the next merge window to go in.
> 
> I can write up a formal patch and let you add it to this patch set as the
> first patch, or I can add it to my tree if you don't expect this to get
> into the next merge window.

The tracepoints that currently use '%.*s' no longer work when
using "trace-cmd start/stop/show". They were working before
9a6944fee68e, so I consider this a regression. I plan to
submit patches to address this for 5.13-rc. I guess they will
have to go without the use of the new _len macros for now,
and you can push the macros in v5.14.


--
Chuck Lever

Re: [PATCH v2 01/25] NFSD: Fix TP_printk() format specifier in trace_nfsd_dirent()

[Steven Rostedt]

On Thu, 13 May 2021 19:08:13 +0000
Chuck Lever III <chuck.lever@oracle.com> wrote:

> The tracepoints that currently use '%.*s' no longer work when
> using "trace-cmd start/stop/show". They were working before
> 9a6944fee68e, so I consider this a regression. I plan to
> submit patches to address this for 5.13-rc. I guess they will
> have to go without the use of the new _len macros for now,
> and you can push the macros in v5.14.

That's a separate bug. I'm currently running this patch through my tests,
and will push to Linus when it completes. Feel free to test this one too.

-- Steve

From eb01f5353bdaa59600b29d864819056a0e3de24d Mon Sep 17 00:00:00 2001
From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>
Date: Thu, 13 May 2021 12:23:24 -0400
Subject: [PATCH] tracing: Handle %.*s in trace_check_vprintf()

If a trace event uses the %*.s notation, the trace_check_vprintf() will
fail and will warn about a bad processing of strings, because it does not
take into account the length field when processing the star (*) part.
Have it handle this case as well.

Link: https://lore.kernel.org/linux-nfs/238C0E2D-C2A4-4578-ADD2-C565B3B99842@oracle.com/

Reported-by: Chuck Lever III <chuck.lever@oracle.com>
Fixes: 9a6944fee68e2 ("tracing: Add a verifier to check string pointers for trace events")
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
 kernel/trace/trace.c | 31 +++++++++++++++++++++++++++----
 1 file changed, 27 insertions(+), 4 deletions(-)

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 560e4c8d3825..a21ef9cd2aae 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -3704,6 +3704,9 @@ void trace_check_vprintf(struct trace_iterator *iter, const char *fmt,
 		goto print;
 
 	while (*p) {
+		bool star = false;
+		int len = 0;
+
 		j = 0;
 
 		/* We only care about %s and variants */
@@ -3725,13 +3728,17 @@ void trace_check_vprintf(struct trace_iterator *iter, const char *fmt,
 				/* Need to test cases like %08.*s */
 				for (j = 1; p[i+j]; j++) {
 					if (isdigit(p[i+j]) ||
-					    p[i+j] == '*' ||
 					    p[i+j] == '.')
 						continue;
+					if (p[i+j] == '*') {
+						star = true;
+						continue;
+					}
 					break;
 				}
 				if (p[i+j] == 's')
 					break;
+				star = false;
 			}
 			j = 0;
 		}
@@ -3744,6 +3751,9 @@ void trace_check_vprintf(struct trace_iterator *iter, const char *fmt,
 		iter->fmt[i] = '\0';
 		trace_seq_vprintf(&iter->seq, iter->fmt, ap);
 
+		if (star)
+			len = va_arg(ap, int);
+
 		/* The ap now points to the string data of the %s */
 		str = va_arg(ap, const char *);
 
@@ -3762,8 +3772,18 @@ void trace_check_vprintf(struct trace_iterator *iter, const char *fmt,
 			int ret;
 
 			/* Try to safely read the string */
-			ret = strncpy_from_kernel_nofault(iter->fmt, str,
-							  iter->fmt_size);
+			if (star) {
+				if (len + 1 > iter->fmt_size)
+					len = iter->fmt_size - 1;
+				if (len < 0)
+					len = 0;
+				ret = copy_from_kernel_nofault(iter->fmt, str, len);
+				iter->fmt[len] = 0;
+				star = false;
+			} else {
+				ret = strncpy_from_kernel_nofault(iter->fmt, str,
+								  iter->fmt_size);
+			}
 			if (ret < 0)
 				trace_seq_printf(&iter->seq, "(0x%px)", str);
 			else
@@ -3775,7 +3795,10 @@ void trace_check_vprintf(struct trace_iterator *iter, const char *fmt,
 			strncpy(iter->fmt, p + i, j + 1);
 			iter->fmt[j+1] = '\0';
 		}
-		trace_seq_printf(&iter->seq, iter->fmt, str);
+		if (star)
+			trace_seq_printf(&iter->seq, iter->fmt, len, str);
+		else
+			trace_seq_printf(&iter->seq, iter->fmt, str);
 
 		p += i + j + 1;
 	}
-- 
2.29.2

Re: [PATCH v2 01/25] NFSD: Fix TP_printk() format specifier in trace_nfsd_dirent()

[Chuck Lever III]

> On May 13, 2021, at 3:17 PM, Steven Rostedt <rostedt@goodmis.org> wrote:
> 
> On Thu, 13 May 2021 19:08:13 +0000
> Chuck Lever III <chuck.lever@oracle.com> wrote:
> 
>> The tracepoints that currently use '%.*s' no longer work when
>> using "trace-cmd start/stop/show". They were working before
>> 9a6944fee68e, so I consider this a regression. I plan to
>> submit patches to address this for 5.13-rc. I guess they will
>> have to go without the use of the new _len macros for now,
>> and you can push the macros in v5.14.
> 
> That's a separate bug. I'm currently running this patch through my tests,
> and will push to Linus when it completes. Feel free to test this one too.

Confirmed that applying the below patch addresses the regression.

Tested-by: Chuck Lever <chuck.lever@oracle.com>

Thanks for your quick response!


> -- Steve
> 
> From eb01f5353bdaa59600b29d864819056a0e3de24d Mon Sep 17 00:00:00 2001
> From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>
> Date: Thu, 13 May 2021 12:23:24 -0400
> Subject: [PATCH] tracing: Handle %.*s in trace_check_vprintf()
> 
> If a trace event uses the %*.s notation, the trace_check_vprintf() will
> fail and will warn about a bad processing of strings, because it does not
> take into account the length field when processing the star (*) part.
> Have it handle this case as well.
> 
> Link: https://lore.kernel.org/linux-nfs/238C0E2D-C2A4-4578-ADD2-C565B3B99842@oracle.com/
> 
> Reported-by: Chuck Lever III <chuck.lever@oracle.com>
> Fixes: 9a6944fee68e2 ("tracing: Add a verifier to check string pointers for trace events")
> Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
> ---
> kernel/trace/trace.c | 31 +++++++++++++++++++++++++++----
> 1 file changed, 27 insertions(+), 4 deletions(-)
> 
> diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
> index 560e4c8d3825..a21ef9cd2aae 100644
> --- a/kernel/trace/trace.c
> +++ b/kernel/trace/trace.c
> @@ -3704,6 +3704,9 @@ void trace_check_vprintf(struct trace_iterator *iter, const char *fmt,
> 		goto print;
> 
> 	while (*p) {
> +		bool star = false;
> +		int len = 0;
> +
> 		j = 0;
> 
> 		/* We only care about %s and variants */
> @@ -3725,13 +3728,17 @@ void trace_check_vprintf(struct trace_iterator *iter, const char *fmt,
> 				/* Need to test cases like %08.*s */
> 				for (j = 1; p[i+j]; j++) {
> 					if (isdigit(p[i+j]) ||
> -					    p[i+j] == '*' ||
> 					    p[i+j] == '.')
> 						continue;
> +					if (p[i+j] == '*') {
> +						star = true;
> +						continue;
> +					}
> 					break;
> 				}
> 				if (p[i+j] == 's')
> 					break;
> +				star = false;
> 			}
> 			j = 0;
> 		}
> @@ -3744,6 +3751,9 @@ void trace_check_vprintf(struct trace_iterator *iter, const char *fmt,
> 		iter->fmt[i] = '\0';
> 		trace_seq_vprintf(&iter->seq, iter->fmt, ap);
> 
> +		if (star)
> +			len = va_arg(ap, int);
> +
> 		/* The ap now points to the string data of the %s */
> 		str = va_arg(ap, const char *);
> 
> @@ -3762,8 +3772,18 @@ void trace_check_vprintf(struct trace_iterator *iter, const char *fmt,
> 			int ret;
> 
> 			/* Try to safely read the string */
> -			ret = strncpy_from_kernel_nofault(iter->fmt, str,
> -							  iter->fmt_size);
> +			if (star) {
> +				if (len + 1 > iter->fmt_size)
> +					len = iter->fmt_size - 1;
> +				if (len < 0)
> +					len = 0;
> +				ret = copy_from_kernel_nofault(iter->fmt, str, len);
> +				iter->fmt[len] = 0;
> +				star = false;
> +			} else {
> +				ret = strncpy_from_kernel_nofault(iter->fmt, str,
> +								  iter->fmt_size);
> +			}
> 			if (ret < 0)
> 				trace_seq_printf(&iter->seq, "(0x%px)", str);
> 			else
> @@ -3775,7 +3795,10 @@ void trace_check_vprintf(struct trace_iterator *iter, const char *fmt,
> 			strncpy(iter->fmt, p + i, j + 1);
> 			iter->fmt[j+1] = '\0';
> 		}
> -		trace_seq_printf(&iter->seq, iter->fmt, str);
> +		if (star)
> +			trace_seq_printf(&iter->seq, iter->fmt, len, str);
> +		else
> +			trace_seq_printf(&iter->seq, iter->fmt, str);
> 
> 		p += i + j + 1;
> 	}
> -- 
> 2.29.2
> 

--
Chuck Lever

Re: [PATCH v2 01/25] NFSD: Fix TP_printk() format specifier in trace_nfsd_dirent()

[Chuck Lever III]

Hello Steven-

> On May 13, 2021, at 10:50 AM, Steven Rostedt <rostedt@goodmis.org> wrote:
> 
> On Wed, 12 May 2021 16:52:05 +0000
> Chuck Lever III <chuck.lever@oracle.com> wrote:
> 
>> The underlying need is to support non-NUL-terminated C strings.
>> 
>> I assumed that since the commentary around 9a6944fee68e claims
>> the proper way to trace C strings is to use __string and friends,
>> and those do not support non-NUL-terminated strings, that such
>> strings are really not first-class citizens. Thus I concluded
>> that my use of '%.*s' was incorrect.
>> 
>> Having some __string-style helpers that can deal with such
>> strings would be valuable.
> 
> I guess the best I can do is a strncpy version, that will add the '\0' in
> the ring buffer. That way we don't need to save the length as well (length
> would need to be at least 4 bytes, where as '\0' is one).
> 
> Something like this?

I don't see this change in v5.14-rc1.


> I added "__string_len()" and "__assign_str_len()". You use them just like
> __string() and __assign_str() but add a max length that you want to use
> (although, it will always allocate "len" regardless if the string is
> smaller). Then use __get_str() just like you use __string().
> 
> Would something like that work?
> 
> -- Steve
> 
> diff --git a/include/trace/trace_events.h b/include/trace/trace_events.h
> index 8268bf747d6f..7ab23535a0c8 100644
> --- a/include/trace/trace_events.h
> +++ b/include/trace/trace_events.h
> @@ -102,6 +102,9 @@ TRACE_MAKE_SYSTEM_STR();
> #undef __string
> #define __string(item, src) __dynamic_array(char, item, -1)
> 
> +#undef __string_len
> +#define __string_len(item, src, len) __dynamic_array(char, item, -1)
> +
> #undef __bitmask
> #define __bitmask(item, nr_bits) __dynamic_array(char, item, -1)
> 
> @@ -197,6 +200,9 @@ TRACE_MAKE_SYSTEM_STR();
> #undef __string
> #define __string(item, src) __dynamic_array(char, item, -1)
> 
> +#undef __string_len
> +#define __string_len(item, src, len) __dynamic_array(char, item, -1)
> +
> #undef __bitmask
> #define __bitmask(item, nr_bits) __dynamic_array(unsigned long, item, -1)
> 
> @@ -444,6 +450,9 @@ static struct trace_event_functions trace_event_type_funcs_##call = {	\
> #undef __string
> #define __string(item, src) __dynamic_array(char, item, -1)
> 
> +#undef __string_len
> +#define __string_len(item, src, len) __dynamic_array(char, item, -1)
> +
> #undef __bitmask
> #define __bitmask(item, nr_bits) __dynamic_array(unsigned long, item, -1)
> 
> @@ -492,6 +501,9 @@ static struct trace_event_fields trace_event_fields_##call[] = {	\
> #define __string(item, src) __dynamic_array(char, item,			\
> 		    strlen((src) ? (const char *)(src) : "(null)") + 1)
> 
> +#undef __string_len
> +#define __string_len(item, src, len) __dynamic_array(char, item, (len) + 1)
> +
> /*
>  * __bitmask_size_in_bytes_raw is the number of bytes needed to hold
>  * num_possible_cpus().
> @@ -655,10 +667,18 @@ static inline notrace int trace_event_get_offsets_##call(		\
> #undef __string
> #define __string(item, src) __dynamic_array(char, item, -1)
> 
> +#undef __string_len
> +#define __string_len(item, src, len) __dynamic_array(char, item, -1)
> +
> #undef __assign_str
> #define __assign_str(dst, src)						\
> 	strcpy(__get_str(dst), (src) ? (const char *)(src) : "(null)");
> 
> +#undef __assign_str_len
> +#define __assign_str_len(dst, src, len)						\
> +	strncpy(__get_str(dst), (src) ? (const char *)(src) : "(null)", len);	\
> +	__get_str(dst)[len] = '\0';
> +
> #undef __bitmask
> #define __bitmask(item, nr_bits) __dynamic_array(unsigned long, item, -1)
> 
> 
> 

--
Chuck Lever

Re: [PATCH v2 01/25] NFSD: Fix TP_printk() format specifier in trace_nfsd_dirent()

[Steven Rostedt]

On Mon, 12 Jul 2021 15:18:05 +0000
Chuck Lever III <chuck.lever@oracle.com> wrote:

> Hello Steven-
> 
> > On May 13, 2021, at 10:50 AM, Steven Rostedt <rostedt@goodmis.org> wrote:
> > 
> > On Wed, 12 May 2021 16:52:05 +0000
> > Chuck Lever III <chuck.lever@oracle.com> wrote:
> >   
> >> The underlying need is to support non-NUL-terminated C strings.
> >> 
> >> I assumed that since the commentary around 9a6944fee68e claims
> >> the proper way to trace C strings is to use __string and friends,
> >> and those do not support non-NUL-terminated strings, that such
> >> strings are really not first-class citizens. Thus I concluded
> >> that my use of '%.*s' was incorrect.
> >> 
> >> Having some __string-style helpers that can deal with such
> >> strings would be valuable.  
> > 
> > I guess the best I can do is a strncpy version, that will add the '\0' in
> > the ring buffer. That way we don't need to save the length as well (length
> > would need to be at least 4 bytes, where as '\0' is one).
> > 
> > Something like this?  
> 
> I don't see this change in v5.14-rc1.

Grumble.

I thought this thread was over with the bug fix that was sent, but
completely forgot about this change, as I never made it into a real commit.

I can add this now, kick off some tests, and grovel to Linus saying that
this is unused code, but other code will depend on this, and I want to get
it upstream so that it can.

-- Steve
> 
> 
> > I added "__string_len()" and "__assign_str_len()". You use them just like
> > __string() and __assign_str() but add a max length that you want to use
> > (although, it will always allocate "len" regardless if the string is
> > smaller). Then use __get_str() just like you use __string().
> > 
> > Would something like that work?
> > 
> > -- Steve
> >