For troubleshooting purposes, record failures to decode NFSv4
operation arguments and encode operation results.
trace_nfsd_compound_decode_err() replaces the dprintk() call sites
that are embedded in READ_* macros that are about to be removed.
Signed-off-by: Chuck Lever <chuck.lever@xxxxxxxxxx>
---
fs/nfsd/nfs4xdr.c | 13 +++++++++-
fs/nfsd/trace.h | 68 +++++++++++++++++++++++++++++++++++++++++++++++++++++
2 files changed, 79 insertions(+), 2 deletions(-)
diff --git a/fs/nfsd/nfs4xdr.c b/fs/nfsd/nfs4xdr.c
index 86a149ce0e84..66edac748272 100644
--- a/fs/nfsd/nfs4xdr.c
+++ b/fs/nfsd/nfs4xdr.c
@@ -54,6 +54,8 @@
#include "pnfs.h"
#include "filecache.h"
+#include "trace.h"
+
#ifdef CONFIG_NFSD_V4_SECURITY_LABEL
#include <linux/security.h>
#endif
@@ -2248,9 +2250,14 @@ nfsd4_decode_compound(struct nfsd4_compoundargs *argp)
READ_BUF(4);
op->opnum = be32_to_cpup(p++);
- if (nfsd4_opnum_in_range(argp, op))
+ if (nfsd4_opnum_in_range(argp, op)) {
op->status = nfsd4_dec_ops[op->opnum](argp, &op->u);
- else {
+ if (op->status != nfs_ok)
+ trace_nfsd_compound_decode_err(argp->rqstp,
+ argp->opcnt, i,
+ op->opnum,
+ op->status);
+ } else {
op->opnum = OP_ILLEGAL;
op->status = nfserr_op_illegal;
}
@@ -5203,6 +5210,8 @@ nfsd4_encode_operation(struct nfsd4_compoundres *resp, struct nfsd4_op *op)
!nfsd4_enc_ops[op->opnum]);
encoder = nfsd4_enc_ops[op->opnum];
op->status = encoder(resp, op->status, &op->u);
+ if (op->status)
+ trace_nfsd_compound_encode_err(rqstp, op->opnum, op->status);
if (opdesc && opdesc->op_release)
opdesc->op_release(&op->u);
xdr_commit_encode(xdr);
diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h
index 0bf1707bd846..92a0973dd671 100644
--- a/fs/nfsd/trace.h
+++ b/fs/nfsd/trace.h
@@ -28,6 +28,24 @@
rqstp->rq_xprt->xpt_remotelen); \
} while (0);
+#define NFSD_TRACE_PROC_RES_FIELDS \
+ __field(unsigned int, netns_ino) \
+ __field(u32, xid) \
+ __field(unsigned long, status) \
+ __array(unsigned char, server, sizeof(struct sockaddr_in6)) \
+ __array(unsigned char, client, sizeof(struct sockaddr_in6))
+
+#define NFSD_TRACE_PROC_RES_ASSIGNMENTS(error) \
+ do { \
+ __entry->netns_ino = SVC_NET(rqstp)->ns.inum; \
+ __entry->xid = be32_to_cpu(rqstp->rq_xid); \
+ __entry->status = be32_to_cpu(error); \
+ memcpy(__entry->server, &rqstp->rq_xprt->xpt_local, \
+ rqstp->rq_xprt->xpt_locallen); \
+ memcpy(__entry->client, &rqstp->rq_xprt->xpt_remote, \
+ rqstp->rq_xprt->xpt_remotelen); \
+ } while (0);
+
TRACE_EVENT(nfsd_garbage_args_err,
TP_PROTO(
const struct svc_rqst *rqstp
@@ -127,6 +145,56 @@ TRACE_EVENT(nfsd_compound_status,
__get_str(name), __entry->status)
)
+TRACE_EVENT(nfsd_compound_decode_err,
+ TP_PROTO(
+ const struct svc_rqst *rqstp,
+ u32 args_opcnt,
+ u32 resp_opcnt,
+ u32 opnum,
+ __be32 status
+ ),
+ TP_ARGS(rqstp, args_opcnt, resp_opcnt, opnum, status),
+ TP_STRUCT__entry(
+ NFSD_TRACE_PROC_RES_FIELDS
+
+ __field(u32, args_opcnt)
+ __field(u32, resp_opcnt)
+ __field(u32, opnum)
+ ),
+ TP_fast_assign(
+ NFSD_TRACE_PROC_RES_ASSIGNMENTS(status)
+
+ __entry->args_opcnt = args_opcnt;
+ __entry->resp_opcnt = resp_opcnt;
+ __entry->opnum = opnum;
+ ),
+ TP_printk("op=%u/%u opnum=%u status=%lu",
+ __entry->resp_opcnt, __entry->args_opcnt,
+ __entry->opnum, __entry->status)
+);
+
+TRACE_EVENT(nfsd_compound_encode_err,
+ TP_PROTO(
+ const struct svc_rqst *rqstp,
+ u32 opnum,
+ __be32 status
+ ),
+ TP_ARGS(rqstp, opnum, status),
+ TP_STRUCT__entry(
+ NFSD_TRACE_PROC_RES_FIELDS
+
+ __field(u32, opnum)
+ ),
+ TP_fast_assign(
+ NFSD_TRACE_PROC_RES_ASSIGNMENTS(status)
+
+ __entry->opnum = opnum;
+ ),
+ TP_printk("opnum=%u status=%lu",
+ __entry->opnum, __entry->status)
+);
+
+
DECLARE_EVENT_CLASS(nfsd_fh_err_class,
TP_PROTO(struct svc_rqst *rqstp,
struct svc_fh *fhp,
