[PATCH 0/3] nfsd: callback debugging improvements

[PATCH 0/3] nfsd: callback debugging improvements

[Jeff Layton]

While working on the delstid patches, I had a couple of bugs that caused
problems during the callback handling. They're now fixed, but these
patches helped me sort out the problems.

Signed-off-by: Jeff Layton <jlayton@kernel.org>
---
Jeff Layton (3):
      nfsd: add more info to WARN_ON_ONCE on failed callbacks
      nfsd: track the main opcode for callbacks
      nfsd: add more nfsd_cb tracepoints

 fs/nfsd/nfs4callback.c |  8 +++++++-
 fs/nfsd/nfs4layouts.c  |  1 +
 fs/nfsd/nfs4proc.c     |  3 ++-
 fs/nfsd/nfs4state.c    |  7 +++++++
 fs/nfsd/state.h        |  1 +
 fs/nfsd/trace.h        | 27 +++++++++++++++++++++++----
 6 files changed, 41 insertions(+), 6 deletions(-)
---
base-commit: 5be63fc19fcaa4c236b307420483578a56986a37
change-id: 20240825-nfsd-cb-1ba377ada62d

Best regards,
-- 
Jeff Layton <jlayton@kernel.org>

[PATCH 1/3] nfsd: add more info to WARN_ON_ONCE on failed callbacks

[Jeff Layton]

Currently, you get the warning and stack trace, but nothing is printed
about the relevant error codes. Add that in.

Signed-off-by: Jeff Layton <jlayton@kernel.org>
---
 fs/nfsd/nfs4callback.c | 3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)

diff --git a/fs/nfsd/nfs4callback.c b/fs/nfsd/nfs4callback.c
index d756f443fc44..dee9477cc5b5 100644
--- a/fs/nfsd/nfs4callback.c
+++ b/fs/nfsd/nfs4callback.c
@@ -1333,7 +1333,8 @@ static void nfsd4_cb_done(struct rpc_task *task, void *calldata)
 		return;
 
 	if (cb->cb_status) {
-		WARN_ON_ONCE(task->tk_status);
+		WARN_ONCE(task->tk_status, "cb_status=%d tk_status=%d",
+			  cb->cb_status, task->tk_status);
 		task->tk_status = cb->cb_status;
 	}
 

-- 
2.46.0

Re: [PATCH 1/3] nfsd: add more info to WARN_ON_ONCE on failed callbacks

[Olga Kornievskaia]

On Mon, Aug 26, 2024 at 8:54 AM Jeff Layton <jlayton@kernel.org> wrote:
>
> Currently, you get the warning and stack trace, but nothing is printed
> about the relevant error codes. Add that in.
>
> Signed-off-by: Jeff Layton <jlayton@kernel.org>
> ---
>  fs/nfsd/nfs4callback.c | 3 ++-
>  1 file changed, 2 insertions(+), 1 deletion(-)
>
> diff --git a/fs/nfsd/nfs4callback.c b/fs/nfsd/nfs4callback.c
> index d756f443fc44..dee9477cc5b5 100644
> --- a/fs/nfsd/nfs4callback.c
> +++ b/fs/nfsd/nfs4callback.c
> @@ -1333,7 +1333,8 @@ static void nfsd4_cb_done(struct rpc_task *task, void *calldata)
>                 return;
>
>         if (cb->cb_status) {
> -               WARN_ON_ONCE(task->tk_status);
> +               WARN_ONCE(task->tk_status, "cb_status=%d tk_status=%d",
> +                         cb->cb_status, task->tk_status);
>                 task->tk_status = cb->cb_status;
>         }

Educational question: why is this warning there in the first place? I
can appreciate the value of information. Does knfsd expect that a
callback should never fail with an error and thus tries to always
catch it? A tracepoint can log an rpc tasks status but I realize that
it doesn't capture attention like a WARN_ON.

I have a report with this warn_on which I'm trying to figure out why
is happening but I was surprised to find nfsd cares so much about the
callback status.

Thank you.
>
>
> --
> 2.46.0
>
>

Re: [PATCH 1/3] nfsd: add more info to WARN_ON_ONCE on failed callbacks

[Jeff Layton]

On Mon, 2024-09-09 at 13:23 -0400, Olga Kornievskaia wrote:
> On Mon, Aug 26, 2024 at 8:54 AM Jeff Layton <jlayton@kernel.org> wrote:
> > 
> > Currently, you get the warning and stack trace, but nothing is printed
> > about the relevant error codes. Add that in.
> > 
> > Signed-off-by: Jeff Layton <jlayton@kernel.org>
> > ---
> >  fs/nfsd/nfs4callback.c | 3 ++-
> >  1 file changed, 2 insertions(+), 1 deletion(-)
> > 
> > diff --git a/fs/nfsd/nfs4callback.c b/fs/nfsd/nfs4callback.c
> > index d756f443fc44..dee9477cc5b5 100644
> > --- a/fs/nfsd/nfs4callback.c
> > +++ b/fs/nfsd/nfs4callback.c
> > @@ -1333,7 +1333,8 @@ static void nfsd4_cb_done(struct rpc_task *task, void *calldata)
> >                 return;
> > 
> >         if (cb->cb_status) {
> > -               WARN_ON_ONCE(task->tk_status);
> > +               WARN_ONCE(task->tk_status, "cb_status=%d tk_status=%d",
> > +                         cb->cb_status, task->tk_status);
> >                 task->tk_status = cb->cb_status;
> >         }
> 
> Educational question: why is this warning there in the first place? I
> can appreciate the value of information. Does knfsd expect that a
> callback should never fail with an error and thus tries to always
> catch it? A tracepoint can log an rpc tasks status but I realize that
> it doesn't capture attention like a WARN_ON.
> 
> I have a report with this warn_on which I'm trying to figure out why
> is happening but I was surprised to find nfsd cares so much about the
> callback status.
> 

This indicates that we had to reissue the RPC, and it got back a second
error. The stack trace is not terribly helpful, IMO. I personally
tripped this while working on the delstid patches, because I had some
bugs in that series initially.

Chuck and I have discussed that the callback channel really needs full
code audit and (probably a real overhaul). The code is just not as
robust as it ought to be, IMO. I've no objection to ripping this
warning out, but it does indicate that the callback "engine" is in a
situation that it may not handle well.
-- 
Jeff Layton <jlayton@kernel.org>

Re: [PATCH 1/3] nfsd: add more info to WARN_ON_ONCE on failed callbacks

[Olga Kornievskaia]

On Mon, Aug 26, 2024 at 8:54 AM Jeff Layton <jlayton@kernel.org> wrote:
>
> Currently, you get the warning and stack trace, but nothing is printed
> about the relevant error codes. Add that in.
>
> Signed-off-by: Jeff Layton <jlayton@kernel.org>
> ---
>  fs/nfsd/nfs4callback.c | 3 ++-
>  1 file changed, 2 insertions(+), 1 deletion(-)
>
> diff --git a/fs/nfsd/nfs4callback.c b/fs/nfsd/nfs4callback.c
> index d756f443fc44..dee9477cc5b5 100644
> --- a/fs/nfsd/nfs4callback.c
> +++ b/fs/nfsd/nfs4callback.c
> @@ -1333,7 +1333,8 @@ static void nfsd4_cb_done(struct rpc_task *task, void *calldata)
>                 return;
>
>         if (cb->cb_status) {
> -               WARN_ON_ONCE(task->tk_status);
> +               WARN_ONCE(task->tk_status, "cb_status=%d tk_status=%d",
> +                         cb->cb_status, task->tk_status);

Can we add cb->cb_ops->opcode to that as well?

>                 task->tk_status = cb->cb_status;
>         }
>
>
> --
> 2.46.0
>
>

Re: [PATCH 1/3] nfsd: add more info to WARN_ON_ONCE on failed callbacks

[Jeff Layton]

On Thu, 2024-12-19 at 16:23 -0500, Olga Kornievskaia wrote:
> On Mon, Aug 26, 2024 at 8:54 AM Jeff Layton <jlayton@kernel.org> wrote:
> > 
> > Currently, you get the warning and stack trace, but nothing is printed
> > about the relevant error codes. Add that in.
> > 
> > Signed-off-by: Jeff Layton <jlayton@kernel.org>
> > ---
> >  fs/nfsd/nfs4callback.c | 3 ++-
> >  1 file changed, 2 insertions(+), 1 deletion(-)
> > 
> > diff --git a/fs/nfsd/nfs4callback.c b/fs/nfsd/nfs4callback.c
> > index d756f443fc44..dee9477cc5b5 100644
> > --- a/fs/nfsd/nfs4callback.c
> > +++ b/fs/nfsd/nfs4callback.c
> > @@ -1333,7 +1333,8 @@ static void nfsd4_cb_done(struct rpc_task *task, void *calldata)
> >                 return;
> > 
> >         if (cb->cb_status) {
> > -               WARN_ON_ONCE(task->tk_status);
> > +               WARN_ONCE(task->tk_status, "cb_status=%d tk_status=%d",
> > +                         cb->cb_status, task->tk_status);
> 
> Can we add cb->cb_ops->opcode to that as well?

I'd be fine with that, but this patch is already merged. Care to
propose one that could go on top?

> 
> >                 task->tk_status = cb->cb_status;
> >         }
> > 
> > 
> > --
> > 2.46.0
> > 
> > 

-- 
Jeff Layton <jlayton@kernel.org>

Re: [PATCH 1/3] nfsd: add more info to WARN_ON_ONCE on failed callbacks

[Olga Kornievskaia]

On Thu, Dec 19, 2024 at 4:33 PM Jeff Layton <jlayton@kernel.org> wrote:
>
> On Thu, 2024-12-19 at 16:23 -0500, Olga Kornievskaia wrote:
> > On Mon, Aug 26, 2024 at 8:54 AM Jeff Layton <jlayton@kernel.org> wrote:
> > >
> > > Currently, you get the warning and stack trace, but nothing is printed
> > > about the relevant error codes. Add that in.
> > >
> > > Signed-off-by: Jeff Layton <jlayton@kernel.org>
> > > ---
> > >  fs/nfsd/nfs4callback.c | 3 ++-
> > >  1 file changed, 2 insertions(+), 1 deletion(-)
> > >
> > > diff --git a/fs/nfsd/nfs4callback.c b/fs/nfsd/nfs4callback.c
> > > index d756f443fc44..dee9477cc5b5 100644
> > > --- a/fs/nfsd/nfs4callback.c
> > > +++ b/fs/nfsd/nfs4callback.c
> > > @@ -1333,7 +1333,8 @@ static void nfsd4_cb_done(struct rpc_task *task, void *calldata)
> > >                 return;
> > >
> > >         if (cb->cb_status) {
> > > -               WARN_ON_ONCE(task->tk_status);
> > > +               WARN_ONCE(task->tk_status, "cb_status=%d tk_status=%d",
> > > +                         cb->cb_status, task->tk_status);
> >
> > Can we add cb->cb_ops->opcode to that as well?
>
> I'd be fine with that, but this patch is already merged. Care to
> propose one that could go on top?

Yep of course was just testing if that was Ok. I just realized it
would have saved a lot of time (me coming up with that fix I just
posted) if I knew what callback was in play.

>
> >
> > >                 task->tk_status = cb->cb_status;
> > >         }
> > >
> > >
> > > --
> > > 2.46.0
> > >
> > >
>
> --
> Jeff Layton <jlayton@kernel.org>

[PATCH 2/3] nfsd: track the main opcode for callbacks

[Jeff Layton]

Keep track of the "main" opcode for the callback, and display it in the
tracepoint. This makes it simpler to discern what's happening when there
is more than one callback in flight.

The one special case is the CB_NULL RPC. That's not a CB_COMPOUND
opcode, so designate the value 0 for that.

Signed-off-by: Jeff Layton <jlayton@kernel.org>
---
 fs/nfsd/nfs4layouts.c |  1 +
 fs/nfsd/nfs4proc.c    |  3 ++-
 fs/nfsd/nfs4state.c   |  4 ++++
 fs/nfsd/state.h       |  1 +
 fs/nfsd/trace.h       | 23 +++++++++++++++++++----
 5 files changed, 27 insertions(+), 5 deletions(-)

diff --git a/fs/nfsd/nfs4layouts.c b/fs/nfsd/nfs4layouts.c
index 4f3072b5979a..fbfddd3c4c94 100644
--- a/fs/nfsd/nfs4layouts.c
+++ b/fs/nfsd/nfs4layouts.c
@@ -740,6 +740,7 @@ static const struct nfsd4_callback_ops nfsd4_cb_layout_ops = {
 	.prepare	= nfsd4_cb_layout_prepare,
 	.done		= nfsd4_cb_layout_done,
 	.release	= nfsd4_cb_layout_release,
+	.opcode		= OP_CB_LAYOUTRECALL,
 };
 
 static bool
diff --git a/fs/nfsd/nfs4proc.c b/fs/nfsd/nfs4proc.c
index 2e39cf2e502a..1dac934686b1 100644
--- a/fs/nfsd/nfs4proc.c
+++ b/fs/nfsd/nfs4proc.c
@@ -1621,7 +1621,8 @@ static int nfsd4_cb_offload_done(struct nfsd4_callback *cb,
 
 static const struct nfsd4_callback_ops nfsd4_cb_offload_ops = {
 	.release = nfsd4_cb_offload_release,
-	.done = nfsd4_cb_offload_done
+	.done = nfsd4_cb_offload_done,
+	.opcode = OP_CB_OFFLOAD,
 };
 
 static void nfsd4_init_copy_res(struct nfsd4_copy *copy, bool sync)
diff --git a/fs/nfsd/nfs4state.c b/fs/nfsd/nfs4state.c
index a20c2c9d7d45..2843f623163d 100644
--- a/fs/nfsd/nfs4state.c
+++ b/fs/nfsd/nfs4state.c
@@ -400,6 +400,7 @@ static const struct nfsd4_callback_ops nfsd4_cb_notify_lock_ops = {
 	.prepare	= nfsd4_cb_notify_lock_prepare,
 	.done		= nfsd4_cb_notify_lock_done,
 	.release	= nfsd4_cb_notify_lock_release,
+	.opcode		= OP_CB_NOTIFY_LOCK,
 };
 
 /*
@@ -3083,11 +3084,13 @@ nfsd4_cb_getattr_release(struct nfsd4_callback *cb)
 static const struct nfsd4_callback_ops nfsd4_cb_recall_any_ops = {
 	.done		= nfsd4_cb_recall_any_done,
 	.release	= nfsd4_cb_recall_any_release,
+	.opcode		= OP_CB_RECALL_ANY,
 };
 
 static const struct nfsd4_callback_ops nfsd4_cb_getattr_ops = {
 	.done		= nfsd4_cb_getattr_done,
 	.release	= nfsd4_cb_getattr_release,
+	.opcode		= OP_CB_GETATTR,
 };
 
 static void nfs4_cb_getattr(struct nfs4_cb_fattr *ncf)
@@ -5215,6 +5218,7 @@ static const struct nfsd4_callback_ops nfsd4_cb_recall_ops = {
 	.prepare	= nfsd4_cb_recall_prepare,
 	.done		= nfsd4_cb_recall_done,
 	.release	= nfsd4_cb_recall_release,
+	.opcode		= OP_CB_RECALL,
 };
 
 static void nfsd_break_one_deleg(struct nfs4_delegation *dp)
diff --git a/fs/nfsd/state.h b/fs/nfsd/state.h
index ffc217099d19..14f9df2bc1ba 100644
--- a/fs/nfsd/state.h
+++ b/fs/nfsd/state.h
@@ -79,6 +79,7 @@ struct nfsd4_callback_ops {
 	void (*prepare)(struct nfsd4_callback *);
 	int (*done)(struct nfsd4_callback *, struct rpc_task *);
 	void (*release)(struct nfsd4_callback *);
+	uint32_t opcode;
 };
 
 /*
diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h
index 77bbd23aa150..476f278e7115 100644
--- a/fs/nfsd/trace.h
+++ b/fs/nfsd/trace.h
@@ -1553,6 +1553,19 @@ TRACE_EVENT(nfsd_cb_setup_err,
 		__entry->error)
 );
 
+/* Not a real opcode, but there is no 0 operation. */
+#define _CB_NULL	0
+
+#define show_nfsd_cb_opcode(val)					\
+	__print_symbolic(val,						\
+		{ _CB_NULL,			"CB_NULL" },		\
+		{ OP_CB_GETATTR,		"CB_GETATTR" },		\
+		{ OP_CB_RECALL,			"CB_RECALL" },		\
+		{ OP_CB_LAYOUTRECALL,		"CB_LAYOUTRECALL" },	\
+		{ OP_CB_RECALL_ANY,		"CB_RECALL_ANY" },	\
+		{ OP_CB_NOTIFY_LOCK,		"CB_NOTIFY_LOCK" },	\
+		{ OP_CB_OFFLOAD,		"CB_OFFLOAD" })
+
 DECLARE_EVENT_CLASS(nfsd_cb_lifetime_class,
 	TP_PROTO(
 		const struct nfs4_client *clp,
@@ -1563,6 +1576,7 @@ DECLARE_EVENT_CLASS(nfsd_cb_lifetime_class,
 		__field(u32, cl_boot)
 		__field(u32, cl_id)
 		__field(const void *, cb)
+		__field(u32, opcode)
 		__field(bool, need_restart)
 		__sockaddr(addr, clp->cl_cb_conn.cb_addrlen)
 	),
@@ -1570,14 +1584,15 @@ DECLARE_EVENT_CLASS(nfsd_cb_lifetime_class,
 		__entry->cl_boot = clp->cl_clientid.cl_boot;
 		__entry->cl_id = clp->cl_clientid.cl_id;
 		__entry->cb = cb;
+		__entry->opcode = cb->cb_ops ? cb->cb_ops->opcode : _CB_NULL;
 		__entry->need_restart = cb->cb_need_restart;
 		__assign_sockaddr(addr, &clp->cl_cb_conn.cb_addr,
 				  clp->cl_cb_conn.cb_addrlen)
 	),
-	TP_printk("addr=%pISpc client %08x:%08x cb=%p%s",
-		__get_sockaddr(addr), __entry->cl_boot, __entry->cl_id,
-		__entry->cb, __entry->need_restart ?
-			" (need restart)" : " (first try)"
+	TP_printk("addr=%pISpc client %08x:%08x cb=%p%s opcode=%s",
+		__get_sockaddr(addr), __entry->cl_boot, __entry->cl_id, __entry->cb,
+		__entry->need_restart ?  " (need restart)" : " (first try)",
+		show_nfsd_cb_opcode(__entry->opcode)
 	)
 );
 

-- 
2.46.0

[PATCH 3/3] nfsd: add more nfsd_cb tracepoints

[Jeff Layton]

Add some tracepoints in the callback client RPC operations. Also
add a tracepoint to nfsd4_cb_getattr_done.

Signed-off-by: Jeff Layton <jlayton@kernel.org>
---
 fs/nfsd/nfs4callback.c | 5 +++++
 fs/nfsd/nfs4state.c    | 3 +++
 fs/nfsd/trace.h        | 4 ++++
 3 files changed, 12 insertions(+)

diff --git a/fs/nfsd/nfs4callback.c b/fs/nfsd/nfs4callback.c
index dee9477cc5b5..b5b3ab9d719a 100644
--- a/fs/nfsd/nfs4callback.c
+++ b/fs/nfsd/nfs4callback.c
@@ -1223,6 +1223,7 @@ static void nfsd4_cb_prepare(struct rpc_task *task, void *calldata)
 	 * cb_seq_status is only set in decode_cb_sequence4res,
 	 * and so will remain 1 if an rpc level failure occurs.
 	 */
+	trace_nfsd_cb_rpc_prepare(clp);
 	cb->cb_seq_status = 1;
 	cb->cb_status = 0;
 	if (minorversion && !nfsd41_cb_get_slot(cb, task))
@@ -1329,6 +1330,8 @@ 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_rpc_done(clp);
+
 	if (!nfsd4_cb_sequence_done(task, cb))
 		return;
 
@@ -1360,6 +1363,8 @@ static void nfsd4_cb_release(void *calldata)
 {
 	struct nfsd4_callback *cb = calldata;
 
+	trace_nfsd_cb_rpc_release(cb->cb_clp);
+
 	if (cb->cb_need_restart)
 		nfsd4_queue_cb(cb);
 	else
diff --git a/fs/nfsd/nfs4state.c b/fs/nfsd/nfs4state.c
index 2843f623163d..918d15fb76b2 100644
--- a/fs/nfsd/nfs4state.c
+++ b/fs/nfsd/nfs4state.c
@@ -3057,7 +3057,10 @@ nfsd4_cb_getattr_done(struct nfsd4_callback *cb, struct rpc_task *task)
 {
 	struct nfs4_cb_fattr *ncf =
 			container_of(cb, struct nfs4_cb_fattr, ncf_getattr);
+	struct nfs4_delegation *dp =
+			container_of(ncf, struct nfs4_delegation, dl_cb_fattr);
 
+	trace_nfsd_cb_getattr_done(&dp->dl_stid.sc_stateid, task);
 	ncf->ncf_cb_status = task->tk_status;
 	switch (task->tk_status) {
 	case -NFS4ERR_DELAY:
diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h
index 476f278e7115..592bf759b85b 100644
--- a/fs/nfsd/trace.h
+++ b/fs/nfsd/trace.h
@@ -1486,6 +1486,9 @@ DEFINE_NFSD_CB_EVENT(new_state);
 DEFINE_NFSD_CB_EVENT(probe);
 DEFINE_NFSD_CB_EVENT(lost);
 DEFINE_NFSD_CB_EVENT(shutdown);
+DEFINE_NFSD_CB_EVENT(rpc_prepare);
+DEFINE_NFSD_CB_EVENT(rpc_done);
+DEFINE_NFSD_CB_EVENT(rpc_release);
 
 TRACE_DEFINE_ENUM(RPC_AUTH_NULL);
 TRACE_DEFINE_ENUM(RPC_AUTH_UNIX);
@@ -1845,6 +1848,7 @@ DEFINE_NFSD_CB_DONE_EVENT(nfsd_cb_recall_done);
 DEFINE_NFSD_CB_DONE_EVENT(nfsd_cb_notify_lock_done);
 DEFINE_NFSD_CB_DONE_EVENT(nfsd_cb_layout_done);
 DEFINE_NFSD_CB_DONE_EVENT(nfsd_cb_offload_done);
+DEFINE_NFSD_CB_DONE_EVENT(nfsd_cb_getattr_done);
 
 TRACE_EVENT(nfsd_cb_recall_any_done,
 	TP_PROTO(

-- 
2.46.0

Re: [PATCH 0/3] nfsd: callback debugging improvements

[Chuck Lever]

On Mon, 26 Aug 2024 08:50:10 -0400, Jeff Layton wrote:
> While working on the delstid patches, I had a couple of bugs that caused
> problems during the callback handling. They're now fixed, but these
> patches helped me sort out the problems.
> 
> 

Applied to nfsd-next for v6.12, thanks!

[1/3] nfsd: add more info to WARN_ON_ONCE on failed callbacks
      commit: 53d519333daf57adc2e682b8316a14afc4dfce6f
[2/3] nfsd: track the main opcode for callbacks
      commit: 17d2b21a691f364710f7ed4192dc3236e44decb0
[3/3] nfsd: add more nfsd_cb tracepoints
      commit: 548ddf619060262afc87db275d644b7f6ee6cbfb

-- 
Chuck Lever