As Jeff recently suggested, here are a few generic patches from my
RPC-with-TLS series that I believe can go in now.
Changes since v1:
- Record presentation addresses in trace_xs_data_ready()
- Drop trace_nfs_mount_addr_err()
---
Chuck Lever (4):
SUNRPC: Fail faster on bad verifier
SUNRPC: Widen rpc_task::tk_flags
SUNRPC: Replace dprintk() call site in xs_data_ready
NFS: Replace fs_context-related dprintk() call sites with tracepoints
fs/nfs/fs_context.c | 24 ++++++++------
fs/nfs/nfstrace.h | 59 +++++++++++++++++++++++++++++++++++
include/linux/sunrpc/clnt.h | 6 ++--
include/linux/sunrpc/sched.h | 32 +++++++++----------
include/trace/events/sunrpc.h | 20 ++++++++++++
net/sunrpc/clnt.c | 13 ++++----
net/sunrpc/debugfs.c | 2 +-
net/sunrpc/xprtsock.c | 6 ++--
8 files changed, 125 insertions(+), 37 deletions(-)
--
Chuck Lever
A bad verifier is not a garbage argument, it's an authentication
failure. Retrying it doesn't make the problem go away, and delays
upper layer recovery steps.
Signed-off-by: Chuck Lever <[email protected]>
Reviewed-by: Jeff Layton <[email protected]>
Signed-off-by: Chuck Lever <[email protected]>
---
net/sunrpc/clnt.c | 2 +-
1 file changed, 1 insertion(+), 1 deletion(-)
diff --git a/net/sunrpc/clnt.c b/net/sunrpc/clnt.c
index b6781ada3aa8..a97d4e06cae3 100644
--- a/net/sunrpc/clnt.c
+++ b/net/sunrpc/clnt.c
@@ -2650,7 +2650,7 @@ rpc_decode_header(struct rpc_task *task, struct xdr_stream *xdr)
out_verifier:
trace_rpc_bad_verifier(task);
- goto out_garbage;
+ goto out_err;
out_msg_denied:
error = -EACCES;
There is just one unused bit left in rpc_task::tk_flags, and I will
need two in subsequent patches. Double the width of the field to
accommodate more flag bits.
Signed-off-by: Chuck Lever <[email protected]>
Reviewed-by: Jeff Layton <[email protected]>
Signed-off-by: Chuck Lever <[email protected]>
---
include/linux/sunrpc/clnt.h | 6 ++++--
include/linux/sunrpc/sched.h | 32 ++++++++++++++++----------------
net/sunrpc/clnt.c | 11 ++++++-----
net/sunrpc/debugfs.c | 2 +-
4 files changed, 27 insertions(+), 24 deletions(-)
diff --git a/include/linux/sunrpc/clnt.h b/include/linux/sunrpc/clnt.h
index 90501404fa49..cbdd20dc84b7 100644
--- a/include/linux/sunrpc/clnt.h
+++ b/include/linux/sunrpc/clnt.h
@@ -193,11 +193,13 @@ void rpc_prepare_reply_pages(struct rpc_rqst *req, struct page **pages,
unsigned int hdrsize);
void rpc_call_start(struct rpc_task *);
int rpc_call_async(struct rpc_clnt *clnt,
- const struct rpc_message *msg, int flags,
+ const struct rpc_message *msg,
+ unsigned int flags,
const struct rpc_call_ops *tk_ops,
void *calldata);
int rpc_call_sync(struct rpc_clnt *clnt,
- const struct rpc_message *msg, int flags);
+ const struct rpc_message *msg,
+ unsigned int flags);
struct rpc_task *rpc_call_null(struct rpc_clnt *clnt, struct rpc_cred *cred,
int flags);
int rpc_restart_call_prepare(struct rpc_task *);
diff --git a/include/linux/sunrpc/sched.h b/include/linux/sunrpc/sched.h
index 1d7a3e51b795..d4b7ebd0a99c 100644
--- a/include/linux/sunrpc/sched.h
+++ b/include/linux/sunrpc/sched.h
@@ -82,7 +82,7 @@ struct rpc_task {
ktime_t tk_start; /* RPC task init timestamp */
pid_t tk_owner; /* Process id for batching tasks */
- unsigned short tk_flags; /* misc flags */
+ unsigned int tk_flags; /* misc flags */
unsigned short tk_timeouts; /* maj timeouts */
#if IS_ENABLED(CONFIG_SUNRPC_DEBUG) || IS_ENABLED(CONFIG_TRACEPOINTS)
@@ -112,27 +112,27 @@ struct rpc_task_setup {
const struct rpc_call_ops *callback_ops;
void *callback_data;
struct workqueue_struct *workqueue;
- unsigned short flags;
+ unsigned int flags;
signed char priority;
};
/*
* RPC task flags
*/
-#define RPC_TASK_ASYNC 0x0001 /* is an async task */
-#define RPC_TASK_SWAPPER 0x0002 /* is swapping in/out */
-#define RPC_TASK_MOVEABLE 0x0004 /* nfs4.1+ rpc tasks */
-#define RPC_TASK_NULLCREDS 0x0010 /* Use AUTH_NULL credential */
-#define RPC_CALL_MAJORSEEN 0x0020 /* major timeout seen */
-#define RPC_TASK_DYNAMIC 0x0080 /* task was kmalloc'ed */
-#define RPC_TASK_NO_ROUND_ROBIN 0x0100 /* send requests on "main" xprt */
-#define RPC_TASK_SOFT 0x0200 /* Use soft timeouts */
-#define RPC_TASK_SOFTCONN 0x0400 /* Fail if can't connect */
-#define RPC_TASK_SENT 0x0800 /* message was sent */
-#define RPC_TASK_TIMEOUT 0x1000 /* fail with ETIMEDOUT on timeout */
-#define RPC_TASK_NOCONNECT 0x2000 /* return ENOTCONN if not connected */
-#define RPC_TASK_NO_RETRANS_TIMEOUT 0x4000 /* wait forever for a reply */
-#define RPC_TASK_CRED_NOREF 0x8000 /* No refcount on the credential */
+#define RPC_TASK_ASYNC 0x00000001 /* is an async task */
+#define RPC_TASK_SWAPPER 0x00000002 /* is swapping in/out */
+#define RPC_TASK_MOVEABLE 0x00000004 /* nfs4.1+ rpc tasks */
+#define RPC_TASK_NULLCREDS 0x00000010 /* Use AUTH_NULL credential */
+#define RPC_CALL_MAJORSEEN 0x00000020 /* major timeout seen */
+#define RPC_TASK_DYNAMIC 0x00000080 /* task was kmalloc'ed */
+#define RPC_TASK_NO_ROUND_ROBIN 0x00000100 /* send requests on "main" xprt */
+#define RPC_TASK_SOFT 0x00000200 /* Use soft timeouts */
+#define RPC_TASK_SOFTCONN 0x00000400 /* Fail if can't connect */
+#define RPC_TASK_SENT 0x00000800 /* message was sent */
+#define RPC_TASK_TIMEOUT 0x00001000 /* fail with ETIMEDOUT on timeout */
+#define RPC_TASK_NOCONNECT 0x00002000 /* return ENOTCONN if not connected */
+#define RPC_TASK_NO_RETRANS_TIMEOUT 0x00004000 /* wait forever for a reply */
+#define RPC_TASK_CRED_NOREF 0x00008000 /* No refcount on the credential */
#define RPC_IS_ASYNC(t) ((t)->tk_flags & RPC_TASK_ASYNC)
#define RPC_IS_SWAPPER(t) ((t)->tk_flags & RPC_TASK_SWAPPER)
diff --git a/net/sunrpc/clnt.c b/net/sunrpc/clnt.c
index a97d4e06cae3..476caa4ebf5c 100644
--- a/net/sunrpc/clnt.c
+++ b/net/sunrpc/clnt.c
@@ -1162,7 +1162,8 @@ EXPORT_SYMBOL_GPL(rpc_run_task);
* @msg: RPC call parameters
* @flags: RPC call flags
*/
-int rpc_call_sync(struct rpc_clnt *clnt, const struct rpc_message *msg, int flags)
+int rpc_call_sync(struct rpc_clnt *clnt, const struct rpc_message *msg,
+ unsigned int flags)
{
struct rpc_task *task;
struct rpc_task_setup task_setup_data = {
@@ -1197,9 +1198,9 @@ EXPORT_SYMBOL_GPL(rpc_call_sync);
* @tk_ops: RPC call ops
* @data: user call data
*/
-int
-rpc_call_async(struct rpc_clnt *clnt, const struct rpc_message *msg, int flags,
- const struct rpc_call_ops *tk_ops, void *data)
+int rpc_call_async(struct rpc_clnt *clnt, const struct rpc_message *msg,
+ unsigned int flags, const struct rpc_call_ops *tk_ops,
+ void *data)
{
struct rpc_task *task;
struct rpc_task_setup task_setup_data = {
@@ -3080,7 +3081,7 @@ static void rpc_show_task(const struct rpc_clnt *clnt,
if (RPC_IS_QUEUED(task))
rpc_waitq = rpc_qname(task->tk_waitqueue);
- printk(KERN_INFO "%5u %04x %6d %8p %8p %8ld %8p %sv%u %s a:%ps q:%s\n",
+ printk(KERN_INFO "%5u %08x %6d %8p %8p %8ld %8p %sv%u %s a:%ps q:%s\n",
task->tk_pid, task->tk_flags, task->tk_status,
clnt, task->tk_rqstp, rpc_task_timeout(task), task->tk_ops,
clnt->cl_program->name, clnt->cl_vers, rpc_proc_name(task),
diff --git a/net/sunrpc/debugfs.c b/net/sunrpc/debugfs.c
index 8df634e63f30..60f20be4e7e5 100644
--- a/net/sunrpc/debugfs.c
+++ b/net/sunrpc/debugfs.c
@@ -30,7 +30,7 @@ tasks_show(struct seq_file *f, void *v)
if (task->tk_rqstp)
xid = be32_to_cpu(task->tk_rqstp->rq_xid);
- seq_printf(f, "%5u %04x %6d 0x%x 0x%x %8ld %ps %sv%u %s a:%ps q:%s\n",
+ seq_printf(f, "%5u %08x %6d 0x%x 0x%x %8ld %ps %sv%u %s a:%ps q:%s\n",
task->tk_pid, task->tk_flags, task->tk_status,
clnt->cl_clid, xid, rpc_task_timeout(task), task->tk_ops,
clnt->cl_program->name, clnt->cl_vers, rpc_proc_name(task),
Signed-off-by: Chuck Lever <[email protected]>
---
include/trace/events/sunrpc.h | 20 ++++++++++++++++++++
net/sunrpc/xprtsock.c | 6 ++++--
2 files changed, 24 insertions(+), 2 deletions(-)
diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h
index b61d9c90fa26..21068ad61db8 100644
--- a/include/trace/events/sunrpc.h
+++ b/include/trace/events/sunrpc.h
@@ -1266,6 +1266,26 @@ TRACE_EVENT(xprt_reserve,
)
);
+TRACE_EVENT(xs_data_ready,
+ TP_PROTO(
+ const struct rpc_xprt *xprt
+ ),
+
+ TP_ARGS(xprt),
+
+ TP_STRUCT__entry(
+ __string(addr, xprt->address_strings[RPC_DISPLAY_ADDR])
+ __string(port, xprt->address_strings[RPC_DISPLAY_PORT])
+ ),
+
+ TP_fast_assign(
+ __assign_str(addr, xprt->address_strings[RPC_DISPLAY_ADDR]);
+ __assign_str(port, xprt->address_strings[RPC_DISPLAY_PORT]);
+ ),
+
+ TP_printk("peer=[%s]:%s", __get_str(addr), __get_str(port))
+);
+
TRACE_EVENT(xs_stream_read_data,
TP_PROTO(struct rpc_xprt *xprt, ssize_t err, size_t total),
diff --git a/net/sunrpc/xprtsock.c b/net/sunrpc/xprtsock.c
index fcdd0fca408e..eba1be9984f8 100644
--- a/net/sunrpc/xprtsock.c
+++ b/net/sunrpc/xprtsock.c
@@ -1378,7 +1378,7 @@ static void xs_udp_data_receive_workfn(struct work_struct *work)
}
/**
- * xs_data_ready - "data ready" callback for UDP sockets
+ * xs_data_ready - "data ready" callback for sockets
* @sk: socket with data to read
*
*/
@@ -1386,11 +1386,13 @@ static void xs_data_ready(struct sock *sk)
{
struct rpc_xprt *xprt;
- dprintk("RPC: xs_data_ready...\n");
xprt = xprt_from_sock(sk);
if (xprt != NULL) {
struct sock_xprt *transport = container_of(xprt,
struct sock_xprt, xprt);
+
+ trace_xs_data_ready(xprt);
+
transport->old_data_ready(sk);
/* Any data means we had a useful conversation, so
* then we don't need to delay the next reconnect
Contributed as part of the long patch series that converts NFS from
using dprintk to tracepoints for observability.
Signed-off-by: Chuck Lever <[email protected]>
Reviewed-by: Jeff Layton <[email protected]>
Signed-off-by: Chuck Lever <[email protected]>
---
fs/nfs/fs_context.c | 24 ++++++++++++---------
fs/nfs/nfstrace.h | 59 +++++++++++++++++++++++++++++++++++++++++++++++++++
2 files changed, 73 insertions(+), 10 deletions(-)
diff --git a/fs/nfs/fs_context.c b/fs/nfs/fs_context.c
index 9a16897e8dc6..6eb3a43920f3 100644
--- a/fs/nfs/fs_context.c
+++ b/fs/nfs/fs_context.c
@@ -21,6 +21,8 @@
#include "nfs.h"
#include "internal.h"
+#include "nfstrace.h"
+
#define NFSDBG_FACILITY NFSDBG_MOUNT
#if IS_ENABLED(CONFIG_NFS_V3)
@@ -284,7 +286,6 @@ static int nfs_verify_server_address(struct sockaddr *addr)
}
}
- dfprintk(MOUNT, "NFS: Invalid IP address specified\n");
return 0;
}
@@ -378,7 +379,7 @@ static int nfs_parse_security_flavors(struct fs_context *fc,
char *string = param->string, *p;
int ret;
- dfprintk(MOUNT, "NFS: parsing %s=%s option\n", param->key, param->string);
+ trace_nfs_mount_assign(param->key, string);
while ((p = strsep(&string, ":")) != NULL) {
if (!*p)
@@ -480,7 +481,7 @@ static int nfs_fs_context_parse_param(struct fs_context *fc,
unsigned int len;
int ret, opt;
- dfprintk(MOUNT, "NFS: parsing nfs mount option '%s'\n", param->key);
+ trace_nfs_mount_option(param);
opt = fs_parse(fc, nfs_fs_parameters, param, &result);
if (opt < 0)
@@ -683,6 +684,7 @@ static int nfs_fs_context_parse_param(struct fs_context *fc,
return ret;
break;
case Opt_vers:
+ trace_nfs_mount_assign(param->key, param->string);
ret = nfs_parse_version_string(fc, param->string);
if (ret < 0)
return ret;
@@ -694,6 +696,7 @@ static int nfs_fs_context_parse_param(struct fs_context *fc,
break;
case Opt_proto:
+ trace_nfs_mount_assign(param->key, param->string);
protofamily = AF_INET;
switch (lookup_constant(nfs_xprt_protocol_tokens, param->string, -1)) {
case Opt_xprt_udp6:
@@ -729,6 +732,7 @@ static int nfs_fs_context_parse_param(struct fs_context *fc,
break;
case Opt_mountproto:
+ trace_nfs_mount_assign(param->key, param->string);
mountfamily = AF_INET;
switch (lookup_constant(nfs_xprt_protocol_tokens, param->string, -1)) {
case Opt_xprt_udp6:
@@ -751,6 +755,7 @@ static int nfs_fs_context_parse_param(struct fs_context *fc,
break;
case Opt_addr:
+ trace_nfs_mount_assign(param->key, param->string);
len = rpc_pton(fc->net_ns, param->string, param->size,
&ctx->nfs_server.address,
sizeof(ctx->nfs_server._address));
@@ -759,16 +764,19 @@ static int nfs_fs_context_parse_param(struct fs_context *fc,
ctx->nfs_server.addrlen = len;
break;
case Opt_clientaddr:
+ trace_nfs_mount_assign(param->key, param->string);
kfree(ctx->client_address);
ctx->client_address = param->string;
param->string = NULL;
break;
case Opt_mounthost:
+ trace_nfs_mount_assign(param->key, param->string);
kfree(ctx->mount_server.hostname);
ctx->mount_server.hostname = param->string;
param->string = NULL;
break;
case Opt_mountaddr:
+ trace_nfs_mount_assign(param->key, param->string);
len = rpc_pton(fc->net_ns, param->string, param->size,
&ctx->mount_server.address,
sizeof(ctx->mount_server._address));
@@ -846,7 +854,6 @@ static int nfs_fs_context_parse_param(struct fs_context *fc,
*/
case Opt_sloppy:
ctx->sloppy = true;
- dfprintk(MOUNT, "NFS: relaxing parsing rules\n");
break;
}
@@ -879,10 +886,8 @@ static int nfs_parse_source(struct fs_context *fc,
size_t len;
const char *end;
- if (unlikely(!dev_name || !*dev_name)) {
- dfprintk(MOUNT, "NFS: device name not specified\n");
+ if (unlikely(!dev_name || !*dev_name))
return -EINVAL;
- }
/* Is the host name protected with square brakcets? */
if (*dev_name == '[') {
@@ -922,7 +927,7 @@ static int nfs_parse_source(struct fs_context *fc,
if (!ctx->nfs_server.export_path)
goto out_nomem;
- dfprintk(MOUNT, "NFS: MNTPATH: '%s'\n", ctx->nfs_server.export_path);
+ trace_nfs_mount_path(ctx->nfs_server.export_path);
return 0;
out_bad_devname:
@@ -1116,7 +1121,6 @@ static int nfs23_parse_monolithic(struct fs_context *fc,
return nfs_invalf(fc, "NFS: nfs_mount_data version supports only AUTH_SYS");
out_nomem:
- dfprintk(MOUNT, "NFS: not enough memory to handle mount options");
return -ENOMEM;
out_no_address:
@@ -1248,7 +1252,7 @@ static int nfs4_parse_monolithic(struct fs_context *fc,
if (IS_ERR(c))
return PTR_ERR(c);
ctx->nfs_server.export_path = c;
- dfprintk(MOUNT, "NFS: MNTPATH: '%s'\n", c);
+ trace_nfs_mount_path(c);
c = strndup_user(data->client_addr.data, 16);
if (IS_ERR(c))
diff --git a/fs/nfs/nfstrace.h b/fs/nfs/nfstrace.h
index 012bd7339862..bd10b556d0d8 100644
--- a/fs/nfs/nfstrace.h
+++ b/fs/nfs/nfstrace.h
@@ -1609,6 +1609,65 @@ TRACE_EVENT(nfs_fh_to_dentry,
)
);
+TRACE_EVENT(nfs_mount_assign,
+ TP_PROTO(
+ const char *option,
+ const char *value
+ ),
+
+ TP_ARGS(option, value),
+
+ TP_STRUCT__entry(
+ __string(option, option)
+ __string(value, value)
+ ),
+
+ TP_fast_assign(
+ __assign_str(option, option);
+ __assign_str(value, value);
+ ),
+
+ TP_printk("option %s=%s",
+ __get_str(option), __get_str(value)
+ )
+);
+
+TRACE_EVENT(nfs_mount_option,
+ TP_PROTO(
+ const struct fs_parameter *param
+ ),
+
+ TP_ARGS(param),
+
+ TP_STRUCT__entry(
+ __string(option, param->key)
+ ),
+
+ TP_fast_assign(
+ __assign_str(option, param->key);
+ ),
+
+ TP_printk("option %s", __get_str(option))
+);
+
+TRACE_EVENT(nfs_mount_path,
+ TP_PROTO(
+ const char *path
+ ),
+
+ TP_ARGS(path),
+
+ TP_STRUCT__entry(
+ __string(path, path)
+ ),
+
+ TP_fast_assign(
+ __assign_str(path, path);
+ ),
+
+ TP_printk("path='%s'", __get_str(path))
+);
+
DECLARE_EVENT_CLASS(nfs_xdr_event,
TP_PROTO(
const struct xdr_stream *xdr,
On Fri, 2022-07-22 at 15:08 -0400, Chuck Lever wrote:
> Signed-off-by: Chuck Lever <[email protected]>
> ---
> include/trace/events/sunrpc.h | 20 ++++++++++++++++++++
> net/sunrpc/xprtsock.c | 6 ++++--
> 2 files changed, 24 insertions(+), 2 deletions(-)
>
> diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h
> index b61d9c90fa26..21068ad61db8 100644
> --- a/include/trace/events/sunrpc.h
> +++ b/include/trace/events/sunrpc.h
> @@ -1266,6 +1266,26 @@ TRACE_EVENT(xprt_reserve,
> )
> );
>
> +TRACE_EVENT(xs_data_ready,
> + TP_PROTO(
> + const struct rpc_xprt *xprt
> + ),
> +
> + TP_ARGS(xprt),
> +
> + TP_STRUCT__entry(
> + __string(addr, xprt->address_strings[RPC_DISPLAY_ADDR])
> + __string(port, xprt->address_strings[RPC_DISPLAY_PORT])
> + ),
> +
> + TP_fast_assign(
> + __assign_str(addr, xprt->address_strings[RPC_DISPLAY_ADDR]);
> + __assign_str(port, xprt->address_strings[RPC_DISPLAY_PORT]);
> + ),
> +
> + TP_printk("peer=[%s]:%s", __get_str(addr), __get_str(port))
> +);
> +
> TRACE_EVENT(xs_stream_read_data,
> TP_PROTO(struct rpc_xprt *xprt, ssize_t err, size_t total),
>
> diff --git a/net/sunrpc/xprtsock.c b/net/sunrpc/xprtsock.c
> index fcdd0fca408e..eba1be9984f8 100644
> --- a/net/sunrpc/xprtsock.c
> +++ b/net/sunrpc/xprtsock.c
> @@ -1378,7 +1378,7 @@ static void xs_udp_data_receive_workfn(struct work_struct *work)
> }
>
> /**
> - * xs_data_ready - "data ready" callback for UDP sockets
> + * xs_data_ready - "data ready" callback for sockets
> * @sk: socket with data to read
> *
> */
> @@ -1386,11 +1386,13 @@ static void xs_data_ready(struct sock *sk)
> {
> struct rpc_xprt *xprt;
>
> - dprintk("RPC: xs_data_ready...\n");
> xprt = xprt_from_sock(sk);
> if (xprt != NULL) {
> struct sock_xprt *transport = container_of(xprt,
> struct sock_xprt, xprt);
> +
> + trace_xs_data_ready(xprt);
> +
> transport->old_data_ready(sk);
> /* Any data means we had a useful conversation, so
> * then we don't need to delay the next reconnect
>
>
Reviewed-by: Jeff Layton <[email protected]>