These tracepoints enable troubleshooting of duplicate clientid strings
and they bracket NFSv4 state recovery. Examples:
NFSv4.0:
nfsd-1037 [000] 1282.828363: nfsd4_compound: xid=0xef35f61d opcnt=1
nfsd-1037 [000] 1282.828488: nfsd_cb_args: client 5f60f8c2:36e7ec84 callback addr=192.168.2.51:38549 prog=1073741824 ident=1
nfsd-1037 [000] 1282.828492: nfsd4_setclientid: xid=0xef35f61d addr=192.168.2.51:0 \
nfs4_clientid=Linux NFSv4.0 manet.1015granger.net/2d9f29bfc60e4c97b19dc38ae1bbed35/192.168.2.55 \
verifier=1631b10 2717d415f client 5f60f8c2:36e7ec84
nfsd-1037 [000] 1282.828496: nfsd4_compoundstatus: xid=0xef35f61d op=1/1 OP_SETCLIENTID status=OK
...
kworker/u8:2-1276 [001] 1802.149078: nfsd4_clid_purged: client 5f60f8c2:36e7ec84
kworker/u8:2-1276 [002] 1802.152047: nfsd4_clid_destroy: client 5f60f8c2:36e7ec84
NFSv4.1:
nfsd-1036 [003] 239.777632: nfsd4_compound: xid=0x746ca73c opcnt=1
nfsd-1036 [003] 239.777776: nfsd4_exchange_id: xid=0x746ca73c addr=192.168.2.51:0 \
nfs4_clientid=Linux NFSv4.1 2d9f29bfc60e4c97b19dc38ae1bbed35/manet.1015granger.net \
verifier=1631b102717d415f flags=SUPP_MOVED_REFER|USE_PNFS_MDS spa_how=SP4_MACH_CRED \
seqid=0 client 5f610879:b615c40a
kworker/u8:4-144 [002] 239.777795: nfsd4_cb_work: addr= client 5f610879:b615c409 procedure=CB_NULL
nfsd-1036 [003] 239.777887: nfsd4_compoundstatus: xid=0x746ca73c op=1/1 OP_EXCHANGE_ID status=OK
nfsd-1036 [003] 239.779793: nfsd4_compound: xid=0x756ca73c opcnt=1
nfsd-1036 [003] 239.780052: nfsd4_cb_state: addr=192.168.2.51:0 client 5f610879:b615c40a state=UNKNOWN
kworker/u8:4-144 [002] 239.780063: nfsd4_cb_work: addr=192.168.2.51:0 client 5f610879:b615c40a procedure=CB_NULL
kworker/u8:4-144 [002] 239.780416: nfsd4_cb_setup: addr=192.168.2.51:0 client 5f610879:b615c40a state=UNKNOWN
nfsd-1036 [000] 239.780433: nfsd4_compoundstatus: xid=0x756ca73c op=1/1 OP_CREATE_SESSION status=OK
nfsd-1036 [000] 239.782856: nfsd4_compound: xid=0x766ca73c opcnt=2
nfsd-1036 [000] 239.782874: nfsd4_compoundstatus: xid=0x766ca73c op=1/2 OP_SEQUENCE status=OK
nfsd-1036 [000] 239.782876: nfsd4_clid_reclaim_complete: client 5f610879:b615c40a
nfsd-1036 [000] 239.785385: nfsd4_compoundstatus: xid=0x766ca73c op=2/2 OP_RECLAIM_COMPLETE status=OK
...
nfsd-1036 [003] 649.644616: nfsd4_compound: xid=0x88d1a73c opcnt=1
nfsd-1036 [003] 649.647841: nfsd4_clid_destroy: client 5f610879:b615c40a
kworker/u8:6-158 [002] 649.647854: nfsd4_cb_work: addr=192.168.2.51:0 client 5f610879:b615c40a procedure=CB_NULL
nfsd-1036 [003] 649.647946: nfsd4_compoundstatus: xid=0x88d1a73c op=1/1 OP_DESTROY_CLIENTID status=OK
Signed-off-by: Chuck Lever <chuck.lever@xxxxxxxxxx>
---
fs/nfsd/nfs4state.c | 37 ++++++---------
fs/nfsd/trace.h | 107 ++++++++++++++++++++++++++++++++------------
fs/nfsd/xdr4.h | 3 +
include/trace/events/nfs.h | 22 +++++++++
4 files changed, 116 insertions(+), 53 deletions(-)
diff --git a/fs/nfsd/nfs4state.c b/fs/nfsd/nfs4state.c
index 0b3059b8b36c..974b3303d2fc 100644
--- a/fs/nfsd/nfs4state.c
+++ b/fs/nfsd/nfs4state.c
@@ -1935,7 +1935,7 @@ STALE_CLIENTID(clientid_t *clid, struct nfsd_net *nn)
*/
if (clid->cl_boot == (u32)nn->boot_time)
return 0;
- trace_nfsd_clid_stale(clid);
+ trace_nfsd4_clid_stale(clid);
return 1;
}
@@ -2077,6 +2077,8 @@ __destroy_client(struct nfs4_client *clp)
struct nfs4_delegation *dp;
struct list_head reaplist;
+ trace_nfsd4_clid_destroy(&clp->cl_clientid);
+
INIT_LIST_HEAD(&reaplist);
spin_lock(&state_lock);
while (!list_empty(&clp->cl_delegations)) {
@@ -3062,18 +3064,10 @@ nfsd4_exchange_id(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate,
struct nfs4_client *conf, *new;
struct nfs4_client *unconf = NULL;
__be32 status;
- char addr_str[INET6_ADDRSTRLEN];
nfs4_verifier verf = exid->verifier;
- struct sockaddr *sa = svc_addr(rqstp);
bool update = exid->flags & EXCHGID4_FLAG_UPD_CONFIRMED_REC_A;
struct nfsd_net *nn = net_generic(SVC_NET(rqstp), nfsd_net_id);
- rpc_ntop(sa, addr_str, sizeof(addr_str));
- dprintk("%s rqstp=%p exid=%p clname.len=%u clname.data=%p "
- "ip_addr=%s flags %x, spa_how %d\n",
- __func__, rqstp, exid, exid->clname.len, exid->clname.data,
- addr_str, exid->flags, exid->spa_how);
-
if (exid->flags & ~EXCHGID4_FLAG_MASK_A)
return nfserr_inval;
@@ -3200,8 +3194,7 @@ nfsd4_exchange_id(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate,
exid->seqid = conf->cl_cs_slot.sl_seqid + 1;
nfsd4_set_ex_flags(conf, exid);
- dprintk("nfsd4_exchange_id seqid %d flags %x\n",
- conf->cl_cs_slot.sl_seqid, conf->cl_exchange_flags);
+ trace_nfsd4_exchange_id(rqstp, exid);
status = nfs_ok;
out:
@@ -3894,8 +3887,11 @@ nfsd4_reclaim_complete(struct svc_rqst *rqstp,
struct nfsd4_compound_state *cstate, union nfsd4_op_u *u)
{
struct nfsd4_reclaim_complete *rc = &u->reclaim_complete;
+ struct nfs4_client *clp = cstate->session->se_client;
__be32 status = 0;
+ trace_nfsd4_clid_reclaim_complete(&clp->cl_clientid);
+
if (rc->rca_one_fs) {
if (!cstate->current_fh.fh_dentry)
return nfserr_nofilehandle;
@@ -3907,12 +3903,11 @@ nfsd4_reclaim_complete(struct svc_rqst *rqstp,
}
status = nfserr_complete_already;
- if (test_and_set_bit(NFSD4_CLIENT_RECLAIM_COMPLETE,
- &cstate->session->se_client->cl_flags))
+ if (test_and_set_bit(NFSD4_CLIENT_RECLAIM_COMPLETE, &clp->cl_flags))
goto out;
status = nfserr_stale_clientid;
- if (is_client_expired(cstate->session->se_client))
+ if (is_client_expired(clp))
/*
* The following error isn't really legal.
* But we only get here if the client just explicitly
@@ -3923,8 +3918,8 @@ nfsd4_reclaim_complete(struct svc_rqst *rqstp,
goto out;
status = nfs_ok;
- nfsd4_client_record_create(cstate->session->se_client);
- inc_reclaim_complete(cstate->session->se_client);
+ nfsd4_client_record_create(clp);
+ inc_reclaim_complete(clp);
out:
return status;
}
@@ -3972,6 +3967,7 @@ nfsd4_setclientid(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate,
setclid->se_clientid.cl_id = new->cl_clientid.cl_id;
memcpy(setclid->se_confirm.data, new->cl_confirm.data, sizeof(setclid->se_confirm.data));
new = NULL;
+ trace_nfsd4_setclientid(rqstp, setclid);
status = nfs_ok;
out:
spin_unlock(&nn->client_lock);
@@ -5314,7 +5310,7 @@ nfsd4_renew(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate,
__be32 status;
struct nfsd_net *nn = net_generic(SVC_NET(rqstp), nfsd_net_id);
- trace_nfsd_clid_renew(clid);
+ trace_nfsd4_clid_renew(clid);
status = lookup_clientid(clid, cstate, nn, false);
if (status)
goto out;
@@ -5426,7 +5422,7 @@ nfs4_laundromat(struct nfsd_net *nn)
break;
}
if (mark_client_expired_locked(clp)) {
- trace_nfsd_clid_expired(&clp->cl_clientid);
+ trace_nfsd4_clid_expired(&clp->cl_clientid);
continue;
}
list_add(&clp->cl_lru, &reaplist);
@@ -5434,7 +5430,7 @@ nfs4_laundromat(struct nfsd_net *nn)
spin_unlock(&nn->client_lock);
list_for_each_safe(pos, next, &reaplist) {
clp = list_entry(pos, struct nfs4_client, cl_lru);
- trace_nfsd_clid_purged(&clp->cl_clientid);
+ trace_nfsd4_clid_purged(&clp->cl_clientid);
list_del_init(&clp->cl_lru);
expire_client(clp);
}
@@ -7185,7 +7181,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);
@@ -7235,8 +7230,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 afcb3bcf13f2..192d039da0ec 100644
--- a/fs/nfsd/trace.h
+++ b/fs/nfsd/trace.h
@@ -14,6 +14,7 @@
#include "export.h"
#include "nfsfh.h"
+#include "xdr4.h"
#define show_nfsd_may_flags(x) \
__print_flags(x, "|", \
@@ -294,6 +295,79 @@ DEFINE_EVENT(nfsd_err_class, nfsd_##name, \
DEFINE_NFSD_ERR_EVENT(read_err);
DEFINE_NFSD_ERR_EVENT(write_err);
+TRACE_EVENT(nfsd4_setclientid,
+ TP_PROTO(
+ const struct svc_rqst *rqstp,
+ const struct nfsd4_setclientid *setclid
+ ),
+ TP_ARGS(rqstp, setclid),
+ TP_STRUCT__entry(
+ __field(u32, xid)
+ __field(u32, cl_boot)
+ __field(u32, cl_id)
+ __array(unsigned char, addr, sizeof(struct sockaddr_in6))
+ __array(char, verifier, NFS4_VERIFIER_SIZE)
+ __field(int, len)
+ __dynamic_array(unsigned char, clientid, setclid->se_name.len)
+ ),
+ TP_fast_assign(
+ __entry->xid = be32_to_cpu(rqstp->rq_xid);
+ __entry->cl_boot = setclid->se_clientid.cl_boot;
+ __entry->cl_id = setclid->se_clientid.cl_id;
+ memcpy(__entry->addr, svc_addr(rqstp), sizeof(struct sockaddr_in6));
+ memcpy(__entry->verifier, &setclid->se_verf, NFS4_VERIFIER_SIZE);
+ __entry->len = setclid->se_name.len;
+ memcpy(__get_dynamic_array(clientid),
+ setclid->se_name.data, setclid->se_name.len);
+ ),
+ TP_printk("xid=0x%08x addr=%pISpc nfs4_clientid=%.*s verifier=%s client=%08x:%08x",
+ __entry->xid, __entry->addr,
+ __entry->len, __get_str(clientid),
+ __print_hex_str(__entry->verifier, NFS4_VERIFIER_SIZE),
+ __entry->cl_boot, __entry->cl_id
+ )
+);
+
+TRACE_EVENT(nfsd4_exchange_id,
+ TP_PROTO(
+ const struct svc_rqst *rqstp,
+ const struct nfsd4_exchange_id *exid
+ ),
+ TP_ARGS(rqstp, exid),
+ TP_STRUCT__entry(
+ __field(u32, xid)
+ __field(u32, seqid)
+ __field(u32, cl_boot)
+ __field(u32, cl_id)
+ __field(unsigned long, flags)
+ __field(unsigned long, spa_how)
+ __array(unsigned char, addr, sizeof(struct sockaddr_in6))
+ __array(char, verifier, NFS4_VERIFIER_SIZE)
+ __field(int, len)
+ __dynamic_array(unsigned char, clientid, exid->clname.len)
+ ),
+ TP_fast_assign(
+ __entry->xid = be32_to_cpu(rqstp->rq_xid);
+ __entry->seqid = exid->seqid - 1;
+ __entry->cl_boot = exid->clientid.cl_boot;
+ __entry->cl_id = exid->clientid.cl_id;
+ __entry->flags = exid->flags;
+ __entry->spa_how = exid->spa_how;
+ memcpy(__entry->addr, svc_addr(rqstp), sizeof(struct sockaddr_in6));
+ memcpy(__entry->verifier, &exid->verifier, NFS4_VERIFIER_SIZE);
+ __entry->len = exid->clname.len;
+ memcpy(__get_dynamic_array(clientid), exid->clname.data, exid->clname.len);
+ ),
+ TP_printk("xid=0x%08x addr=%pISpc nfs4_clientid=%.*s verifier=%s flags=%s spa_how=%s seqid=%u client=%08x:%08x",
+ __entry->xid, __entry->addr,
+ __entry->len, __get_str(clientid),
+ __print_hex_str(__entry->verifier, NFS4_VERIFIER_SIZE),
+ show_nfs4_exchgid4_flags(__entry->flags),
+ show_nfs4_exchid4_spa_how(__entry->spa_how),
+ __entry->seqid, __entry->cl_boot, __entry->cl_id
+ )
+);
+
TRACE_EVENT(nfsd4_compound,
TP_PROTO(
const struct svc_rqst *rqstp,
@@ -433,10 +507,12 @@ DECLARE_EVENT_CLASS(nfsd_clientid_class,
)
#define DEFINE_CLIENTID_EVENT(name) \
-DEFINE_EVENT(nfsd_clientid_class, nfsd_clid_##name, \
+DEFINE_EVENT(nfsd_clientid_class, nfsd4_clid_##name, \
TP_PROTO(const clientid_t *clid), \
TP_ARGS(clid))
+DEFINE_CLIENTID_EVENT(reclaim_complete);
+DEFINE_CLIENTID_EVENT(destroy);
DEFINE_CLIENTID_EVENT(expired);
DEFINE_CLIENTID_EVENT(purged);
DEFINE_CLIENTID_EVENT(renew);
@@ -462,35 +538,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),
diff --git a/fs/nfsd/xdr4.h b/fs/nfsd/xdr4.h
index 66499fb6b567..9267a4775263 100644
--- a/fs/nfsd/xdr4.h
+++ b/fs/nfsd/xdr4.h
@@ -763,6 +763,7 @@ void warn_on_nonidempotent_op(struct nfsd4_op *op);
#define NFS4_SVC_XDRSIZE sizeof(struct nfsd4_compoundargs)
+#ifdef CONFIG_NFSD_V3
static inline void
set_change_info(struct nfsd4_change_info *cinfo, struct svc_fh *fhp)
{
@@ -778,7 +779,7 @@ set_change_info(struct nfsd4_change_info *cinfo, struct svc_fh *fhp)
cinfo->after_ctime_nsec = fhp->fh_post_attr.ctime.tv_nsec;
}
-
+#endif /* CONFIG_NFSD_V3 */
bool nfsd4_mach_creds_match(struct nfs4_client *cl, struct svc_rqst *rqstp);
int nfs4svc_encode_voidres(struct svc_rqst *, __be32 *);
diff --git a/include/trace/events/nfs.h b/include/trace/events/nfs.h
index 8e3de3b421f4..76f661e8cdf4 100644
--- a/include/trace/events/nfs.h
+++ b/include/trace/events/nfs.h
@@ -359,3 +359,25 @@ TRACE_DEFINE_ENUM(NFS_FILE_SYNC);
{ SEQ4_STATUS_RESTART_RECLAIM_NEEDED, "RESTART_RECLAIM_NEEDED" }, \
{ SEQ4_STATUS_CB_PATH_DOWN_SESSION, "CB_PATH_DOWN_SESSION" }, \
{ SEQ4_STATUS_BACKCHANNEL_FAULT, "BACKCHANNEL_FAULT" })
+
+#define show_nfs4_exchgid4_flags(x) \
+ __print_flags(x, "|", \
+ { EXCHGID4_FLAG_SUPP_MOVED_REFER, "SUPP_MOVED_REFER" }, \
+ { EXCHGID4_FLAG_SUPP_MOVED_MIGR, "SUPP_MOVED_MIGR" }, \
+ { EXCHGID4_FLAG_BIND_PRINC_STATEID, "BIND_PRINC_STATEID" }, \
+ { EXCHGID4_FLAG_USE_NON_PNFS, "USE_NON_PNFS" }, \
+ { EXCHGID4_FLAG_USE_PNFS_MDS, "USE_PNFS_MDS" }, \
+ { EXCHGID4_FLAG_USE_PNFS_DS, "USE_PNFS_DS" }, \
+ { EXCHGID4_FLAG_MASK_PNFS, "MASK_PNFS" }, \
+ { EXCHGID4_FLAG_UPD_CONFIRMED_REC_A, "UPD_CONFIRMED_REC_A" }, \
+ { EXCHGID4_FLAG_CONFIRMED_R, "CONFIRMED_R" })
+
+TRACE_DEFINE_ENUM(SP4_NONE);
+TRACE_DEFINE_ENUM(SP4_MACH_CRED);
+TRACE_DEFINE_ENUM(SP4_SSV);
+
+#define show_nfs4_exchid4_spa_how(x) \
+ __print_symbolic(x, \
+ { SP4_NONE, "NONE" }, \
+ { SP4_MACH_CRED, "MACH_CRED" }, \
+ { SP4_SSV, "SSV" })
