2019-10-25 11:53:06

by Chuck Lever III

[permalink] [raw]
Subject: [PATCH v1 1/2] SUNRPC: Trace gssproxy upcall results

Record results of a GSS proxy ACCEPT_SEC_CONTEXT upcall and the
svc_authenticate() function to make field debugging of NFS server
Kerberos issues easier.

Signed-off-by: Chuck Lever <[email protected]>
Reviewed-by: Bill Baker <[email protected]>
---
include/trace/events/rpcgss.h | 45 +++++++++++++++++++++++++++
include/trace/events/sunrpc.h | 55 +++++++++++++++++++++++++++++++++
net/sunrpc/auth_gss/gss_mech_switch.c | 4 ++
net/sunrpc/auth_gss/svcauth_gss.c | 8 +++--
net/sunrpc/svc.c | 2 +
net/sunrpc/svcauth.c | 2 +
6 files changed, 112 insertions(+), 4 deletions(-)

diff --git a/include/trace/events/rpcgss.h b/include/trace/events/rpcgss.h
index d1f7fe1..9827f53 100644
--- a/include/trace/events/rpcgss.h
+++ b/include/trace/events/rpcgss.h
@@ -126,6 +126,34 @@
DEFINE_GSSAPI_EVENT(wrap);
DEFINE_GSSAPI_EVENT(unwrap);

+TRACE_EVENT(rpcgss_accept_upcall,
+ TP_PROTO(
+ __be32 xid,
+ u32 major_status,
+ u32 minor_status
+ ),
+
+ TP_ARGS(xid, major_status, minor_status),
+
+ TP_STRUCT__entry(
+ __field(u32, xid)
+ __field(u32, minor_status)
+ __field(unsigned long, major_status)
+ ),
+
+ TP_fast_assign(
+ __entry->xid = be32_to_cpu(xid);
+ __entry->minor_status = minor_status;
+ __entry->major_status = major_status;
+ ),
+
+ TP_printk("xid=0x%08x major_status=%s (0x%08lx) minor_status=%u",
+ __entry->xid, __entry->major_status == 0 ? "GSS_S_COMPLETE" :
+ show_gss_status(__entry->major_status),
+ __entry->major_status, __entry->minor_status
+ )
+);
+

/**
** GSS auth unwrap failures
@@ -355,6 +383,23 @@
show_pseudoflavor(__entry->flavor), __entry->error)
);

+TRACE_EVENT(rpcgss_oid_to_mech,
+ TP_PROTO(
+ const char *oid
+ ),
+
+ TP_ARGS(oid),
+
+ TP_STRUCT__entry(
+ __string(oid, oid)
+ ),
+
+ TP_fast_assign(
+ __assign_str(oid, oid);
+ ),
+
+ TP_printk("mech for oid %s was not found", __get_str(oid))
+);

#endif /* _TRACE_RPCGSS_H */

diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h
index ffa3c51..c358a0a 100644
--- a/include/trace/events/sunrpc.h
+++ b/include/trace/events/sunrpc.h
@@ -14,6 +14,26 @@
#include <linux/net.h>
#include <linux/tracepoint.h>

+TRACE_DEFINE_ENUM(RPC_AUTH_OK);
+TRACE_DEFINE_ENUM(RPC_AUTH_BADCRED);
+TRACE_DEFINE_ENUM(RPC_AUTH_REJECTEDCRED);
+TRACE_DEFINE_ENUM(RPC_AUTH_BADVERF);
+TRACE_DEFINE_ENUM(RPC_AUTH_REJECTEDVERF);
+TRACE_DEFINE_ENUM(RPC_AUTH_TOOWEAK);
+TRACE_DEFINE_ENUM(RPCSEC_GSS_CREDPROBLEM);
+TRACE_DEFINE_ENUM(RPCSEC_GSS_CTXPROBLEM);
+
+#define rpc_show_auth_stat(status) \
+ __print_symbolic(status, \
+ { RPC_AUTH_OK, "AUTH_OK" }, \
+ { RPC_AUTH_BADCRED, "BADCRED" }, \
+ { RPC_AUTH_REJECTEDCRED, "REJECTEDCRED" }, \
+ { RPC_AUTH_BADVERF, "BADVERF" }, \
+ { RPC_AUTH_REJECTEDVERF, "REJECTEDVERF" }, \
+ { RPC_AUTH_TOOWEAK, "TOOWEAK" }, \
+ { RPCSEC_GSS_CREDPROBLEM, "GSS_CREDPROBLEM" }, \
+ { RPCSEC_GSS_CTXPROBLEM, "GSS_CTXPROBLEM" }) \
+
DECLARE_EVENT_CLASS(rpc_task_status,

TP_PROTO(const struct rpc_task *task),
@@ -866,6 +886,41 @@
show_rqstp_flags(__entry->flags))
);

+#define svc_show_status(status) \
+ __print_symbolic(status, \
+ { SVC_GARBAGE, "SVC_GARBAGE" }, \
+ { SVC_SYSERR, "SVC_SYSERR" }, \
+ { SVC_VALID, "SVC_VALID" }, \
+ { SVC_NEGATIVE, "SVC_NEGATIVE" }, \
+ { SVC_OK, "SVC_OK" }, \
+ { SVC_DROP, "SVC_DROP" }, \
+ { SVC_CLOSE, "SVC_CLOSE" }, \
+ { SVC_DENIED, "SVC_DENIED" }, \
+ { SVC_PENDING, "SVC_PENDING" }, \
+ { SVC_COMPLETE, "SVC_COMPLETE" })
+
+TRACE_EVENT(svc_authenticate,
+ TP_PROTO(const struct svc_rqst *rqst, int auth_res, __be32 auth_stat),
+
+ TP_ARGS(rqst, auth_res, auth_stat),
+
+ TP_STRUCT__entry(
+ __field(u32, xid)
+ __field(unsigned long, svc_status)
+ __field(unsigned long, auth_stat)
+ ),
+
+ TP_fast_assign(
+ __entry->xid = be32_to_cpu(rqst->rq_xid);
+ __entry->svc_status = auth_res;
+ __entry->auth_stat = be32_to_cpu(auth_stat);
+ ),
+
+ TP_printk("xid=0x%08x auth_res=%s auth_stat=%s",
+ __entry->xid, svc_show_status(__entry->svc_status),
+ rpc_show_auth_stat(__entry->auth_stat))
+);
+
TRACE_EVENT(svc_process,
TP_PROTO(const struct svc_rqst *rqst, const char *name),

diff --git a/net/sunrpc/auth_gss/gss_mech_switch.c b/net/sunrpc/auth_gss/gss_mech_switch.c
index 8206009..30b7de6 100644
--- a/net/sunrpc/auth_gss/gss_mech_switch.c
+++ b/net/sunrpc/auth_gss/gss_mech_switch.c
@@ -20,6 +20,7 @@
#include <linux/sunrpc/sched.h>
#include <linux/sunrpc/gss_api.h>
#include <linux/sunrpc/clnt.h>
+#include <trace/events/rpcgss.h>

#if IS_ENABLED(CONFIG_SUNRPC_DEBUG)
# define RPCDBG_FACILITY RPCDBG_AUTH
@@ -158,7 +159,6 @@ struct gss_api_mech *gss_mech_get_by_OID(struct rpcsec_gss_oid *obj)

if (sprint_oid(obj->data, obj->len, buf, sizeof(buf)) < 0)
return NULL;
- dprintk("RPC: %s(%s)\n", __func__, buf);
request_module("rpc-auth-gss-%s", buf);

rcu_read_lock();
@@ -172,6 +172,8 @@ struct gss_api_mech *gss_mech_get_by_OID(struct rpcsec_gss_oid *obj)
}
}
rcu_read_unlock();
+ if (!gm)
+ trace_rpcgss_oid_to_mech(buf);
return gm;
}

diff --git a/net/sunrpc/auth_gss/svcauth_gss.c b/net/sunrpc/auth_gss/svcauth_gss.c
index 8be2f20..f130990 100644
--- a/net/sunrpc/auth_gss/svcauth_gss.c
+++ b/net/sunrpc/auth_gss/svcauth_gss.c
@@ -49,6 +49,9 @@
#include <linux/sunrpc/svcauth.h>
#include <linux/sunrpc/svcauth_gss.h>
#include <linux/sunrpc/cache.h>
+
+#include <trace/events/rpcgss.h>
+
#include "gss_rpc_upcall.h"


@@ -1270,9 +1273,8 @@ static int svcauth_gss_proxy_init(struct svc_rqst *rqstp,
if (status)
goto out;

- dprintk("RPC: svcauth_gss: gss major status = %d "
- "minor status = %d\n",
- ud.major_status, ud.minor_status);
+ trace_rpcgss_accept_upcall(rqstp->rq_xid, ud.major_status,
+ ud.minor_status);

switch (ud.major_status) {
case GSS_S_CONTINUE_NEEDED:
diff --git a/net/sunrpc/svc.c b/net/sunrpc/svc.c
index d11b705..187dd4e 100644
--- a/net/sunrpc/svc.c
+++ b/net/sunrpc/svc.c
@@ -1337,6 +1337,8 @@ static __printf(2,3) void svc_printk(struct svc_rqst *rqstp, const char *fmt, ..
auth_stat = rpc_autherr_badcred;
auth_res = progp->pg_authenticate(rqstp);
}
+ if (auth_res != SVC_OK)
+ trace_svc_authenticate(rqstp, auth_res, auth_stat);
switch (auth_res) {
case SVC_OK:
break;
diff --git a/net/sunrpc/svcauth.c b/net/sunrpc/svcauth.c
index 550b214..552617e 100644
--- a/net/sunrpc/svcauth.c
+++ b/net/sunrpc/svcauth.c
@@ -19,6 +19,8 @@
#include <linux/err.h>
#include <linux/hash.h>

+#include <trace/events/sunrpc.h>
+
#define RPCDBG_FACILITY RPCDBG_AUTH




2019-10-25 11:53:56

by Chuck Lever III

[permalink] [raw]
Subject: [PATCH v1 2/2] SUNRPC: Fix svcauth_gss_proxy_init()

gss_read_proxy_verf() assumes things about the XDR buffer containing
the RPC Call that are not true for buffers generated by
svc_rdma_recv().

RDMA's buffers look more like what the upper layer generates for
sending: head is a kmalloc'd buffer; it does not point to a page
whose contents are contiguous with the first page in the buffers'
page array. The result is that ACCEPT_SEC_CONTEXT via RPC/RDMA has
stopped working on Linux NFS servers that use gssproxy.

This does not affect clients that use only TCP to send their
ACCEPT_SEC_CONTEXT operation (that's all Linux clients). Other
clients, like Solaris NFS clients, send ACCEPT_SEC_CONTEXT on the
same transport as they send all other NFS operations. Such clients
can send ACCEPT_SEC_CONTEXT via RPC/RDMA.

I thought I had found every direct reference in the server RPC code
to the rqstp->rq_pages field.

Bug found at the 2019 Westford NFS bake-a-thon.

Fixes: 3316f0631139 ("svcrdma: Persistently allocate and DMA- ... ")
Signed-off-by: Chuck Lever <[email protected]>
Tested-by: Bill Baker <[email protected]>
---
net/sunrpc/auth_gss/svcauth_gss.c | 84 ++++++++++++++++++++++++++++---------
1 file changed, 63 insertions(+), 21 deletions(-)

diff --git a/net/sunrpc/auth_gss/svcauth_gss.c b/net/sunrpc/auth_gss/svcauth_gss.c
index f130990..c62d1f1 100644
--- a/net/sunrpc/auth_gss/svcauth_gss.c
+++ b/net/sunrpc/auth_gss/svcauth_gss.c
@@ -1078,24 +1078,32 @@ struct gss_svc_data {
return 0;
}

-/* Ok this is really heavily depending on a set of semantics in
- * how rqstp is set up by svc_recv and pages laid down by the
- * server when reading a request. We are basically guaranteed that
- * the token lays all down linearly across a set of pages, starting
- * at iov_base in rq_arg.head[0] which happens to be the first of a
- * set of pages stored in rq_pages[].
- * rq_arg.head[0].iov_base will provide us the page_base to pass
- * to the upcall.
- */
-static inline int
-gss_read_proxy_verf(struct svc_rqst *rqstp,
- struct rpc_gss_wire_cred *gc, __be32 *authp,
- struct xdr_netobj *in_handle,
- struct gssp_in_token *in_token)
+static void gss_free_in_token_pages(struct gssp_in_token *in_token)
{
- struct kvec *argv = &rqstp->rq_arg.head[0];
u32 inlen;
- int res;
+ int i;
+
+ i = 0;
+ inlen = in_token->page_len;
+ while (inlen) {
+ if (in_token->pages[i])
+ put_page(in_token->pages[i]);
+ inlen -= inlen > PAGE_SIZE ? PAGE_SIZE : inlen;
+ }
+
+ kfree(in_token->pages);
+ in_token->pages = NULL;
+}
+
+static int gss_read_proxy_verf(struct svc_rqst *rqstp,
+ struct rpc_gss_wire_cred *gc, __be32 *authp,
+ struct xdr_netobj *in_handle,
+ struct gssp_in_token *in_token)
+{
+ struct kvec *argv = &rqstp->rq_arg.head[0];
+ unsigned int page_base, length;
+ int pages, i, res;
+ size_t inlen;

res = gss_read_common_verf(gc, argv, authp, in_handle);
if (res)
@@ -1105,10 +1113,36 @@ struct gss_svc_data {
if (inlen > (argv->iov_len + rqstp->rq_arg.page_len))
return SVC_DENIED;

- in_token->pages = rqstp->rq_pages;
- in_token->page_base = (ulong)argv->iov_base & ~PAGE_MASK;
+ pages = DIV_ROUND_UP(inlen, PAGE_SIZE);
+ in_token->pages = kcalloc(pages, sizeof(struct page *), GFP_KERNEL);
+ if (!in_token->pages)
+ return SVC_DENIED;
+ in_token->page_base = 0;
in_token->page_len = inlen;
+ for (i = 0; i < pages; i++) {
+ in_token->pages[i] = alloc_page(GFP_KERNEL);
+ if (!in_token->pages[i]) {
+ gss_free_in_token_pages(in_token);
+ return SVC_DENIED;
+ }
+ }

+ length = min_t(unsigned int, inlen, argv->iov_len);
+ memcpy(page_address(in_token->pages[0]), argv->iov_base, length);
+ inlen -= length;
+
+ i = 1;
+ page_base = rqstp->rq_arg.page_base;
+ while (inlen) {
+ length = min_t(unsigned int, inlen, PAGE_SIZE);
+ memcpy(page_address(in_token->pages[i]),
+ page_address(rqstp->rq_arg.pages[i]) + page_base,
+ length);
+
+ inlen -= length;
+ page_base = 0;
+ i++;
+ }
return 0;
}

@@ -1282,8 +1316,11 @@ static int svcauth_gss_proxy_init(struct svc_rqst *rqstp,
break;
case GSS_S_COMPLETE:
status = gss_proxy_save_rsc(sn->rsc_cache, &ud, &handle);
- if (status)
+ if (status) {
+ pr_info("%s: gss_proxy_save_rsc failed (%d)\n",
+ __func__, status);
goto out;
+ }
cli_handle.data = (u8 *)&handle;
cli_handle.len = sizeof(handle);
break;
@@ -1294,15 +1331,20 @@ static int svcauth_gss_proxy_init(struct svc_rqst *rqstp,

/* Got an answer to the upcall; use it: */
if (gss_write_init_verf(sn->rsc_cache, rqstp,
- &cli_handle, &ud.major_status))
+ &cli_handle, &ud.major_status)) {
+ pr_info("%s: gss_write_init_verf failed\n", __func__);
goto out;
+ }
if (gss_write_resv(resv, PAGE_SIZE,
&cli_handle, &ud.out_token,
- ud.major_status, ud.minor_status))
+ ud.major_status, ud.minor_status)) {
+ pr_info("%s: gss_write_resv failed\n", __func__);
goto out;
+ }

ret = SVC_COMPLETE;
out:
+ gss_free_in_token_pages(&ud.in_token);
gssp_free_upcall_data(&ud);
return ret;
}

2019-10-25 14:04:45

by J. Bruce Fields

[permalink] [raw]
Subject: Re: [PATCH v1 1/2] SUNRPC: Trace gssproxy upcall results

On Thu, Oct 24, 2019 at 09:34:10AM -0400, Chuck Lever wrote:
> Record results of a GSS proxy ACCEPT_SEC_CONTEXT upcall and the
> svc_authenticate() function to make field debugging of NFS server
> Kerberos issues easier.

Inclined to apply.

The only thing that bugs me a bit is that this is just summarizing
information that's passing between the kernel and userspace--so it seems
like a job for strace or wireshark or something.

--b.

>
> Signed-off-by: Chuck Lever <[email protected]>
> Reviewed-by: Bill Baker <[email protected]>
> ---
> include/trace/events/rpcgss.h | 45 +++++++++++++++++++++++++++
> include/trace/events/sunrpc.h | 55 +++++++++++++++++++++++++++++++++
> net/sunrpc/auth_gss/gss_mech_switch.c | 4 ++
> net/sunrpc/auth_gss/svcauth_gss.c | 8 +++--
> net/sunrpc/svc.c | 2 +
> net/sunrpc/svcauth.c | 2 +
> 6 files changed, 112 insertions(+), 4 deletions(-)
>
> diff --git a/include/trace/events/rpcgss.h b/include/trace/events/rpcgss.h
> index d1f7fe1..9827f53 100644
> --- a/include/trace/events/rpcgss.h
> +++ b/include/trace/events/rpcgss.h
> @@ -126,6 +126,34 @@
> DEFINE_GSSAPI_EVENT(wrap);
> DEFINE_GSSAPI_EVENT(unwrap);
>
> +TRACE_EVENT(rpcgss_accept_upcall,
> + TP_PROTO(
> + __be32 xid,
> + u32 major_status,
> + u32 minor_status
> + ),
> +
> + TP_ARGS(xid, major_status, minor_status),
> +
> + TP_STRUCT__entry(
> + __field(u32, xid)
> + __field(u32, minor_status)
> + __field(unsigned long, major_status)
> + ),
> +
> + TP_fast_assign(
> + __entry->xid = be32_to_cpu(xid);
> + __entry->minor_status = minor_status;
> + __entry->major_status = major_status;
> + ),
> +
> + TP_printk("xid=0x%08x major_status=%s (0x%08lx) minor_status=%u",
> + __entry->xid, __entry->major_status == 0 ? "GSS_S_COMPLETE" :
> + show_gss_status(__entry->major_status),
> + __entry->major_status, __entry->minor_status
> + )
> +);
> +
>
> /**
> ** GSS auth unwrap failures
> @@ -355,6 +383,23 @@
> show_pseudoflavor(__entry->flavor), __entry->error)
> );
>
> +TRACE_EVENT(rpcgss_oid_to_mech,
> + TP_PROTO(
> + const char *oid
> + ),
> +
> + TP_ARGS(oid),
> +
> + TP_STRUCT__entry(
> + __string(oid, oid)
> + ),
> +
> + TP_fast_assign(
> + __assign_str(oid, oid);
> + ),
> +
> + TP_printk("mech for oid %s was not found", __get_str(oid))
> +);
>
> #endif /* _TRACE_RPCGSS_H */
>
> diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h
> index ffa3c51..c358a0a 100644
> --- a/include/trace/events/sunrpc.h
> +++ b/include/trace/events/sunrpc.h
> @@ -14,6 +14,26 @@
> #include <linux/net.h>
> #include <linux/tracepoint.h>
>
> +TRACE_DEFINE_ENUM(RPC_AUTH_OK);
> +TRACE_DEFINE_ENUM(RPC_AUTH_BADCRED);
> +TRACE_DEFINE_ENUM(RPC_AUTH_REJECTEDCRED);
> +TRACE_DEFINE_ENUM(RPC_AUTH_BADVERF);
> +TRACE_DEFINE_ENUM(RPC_AUTH_REJECTEDVERF);
> +TRACE_DEFINE_ENUM(RPC_AUTH_TOOWEAK);
> +TRACE_DEFINE_ENUM(RPCSEC_GSS_CREDPROBLEM);
> +TRACE_DEFINE_ENUM(RPCSEC_GSS_CTXPROBLEM);
> +
> +#define rpc_show_auth_stat(status) \
> + __print_symbolic(status, \
> + { RPC_AUTH_OK, "AUTH_OK" }, \
> + { RPC_AUTH_BADCRED, "BADCRED" }, \
> + { RPC_AUTH_REJECTEDCRED, "REJECTEDCRED" }, \
> + { RPC_AUTH_BADVERF, "BADVERF" }, \
> + { RPC_AUTH_REJECTEDVERF, "REJECTEDVERF" }, \
> + { RPC_AUTH_TOOWEAK, "TOOWEAK" }, \
> + { RPCSEC_GSS_CREDPROBLEM, "GSS_CREDPROBLEM" }, \
> + { RPCSEC_GSS_CTXPROBLEM, "GSS_CTXPROBLEM" }) \
> +
> DECLARE_EVENT_CLASS(rpc_task_status,
>
> TP_PROTO(const struct rpc_task *task),
> @@ -866,6 +886,41 @@
> show_rqstp_flags(__entry->flags))
> );
>
> +#define svc_show_status(status) \
> + __print_symbolic(status, \
> + { SVC_GARBAGE, "SVC_GARBAGE" }, \
> + { SVC_SYSERR, "SVC_SYSERR" }, \
> + { SVC_VALID, "SVC_VALID" }, \
> + { SVC_NEGATIVE, "SVC_NEGATIVE" }, \
> + { SVC_OK, "SVC_OK" }, \
> + { SVC_DROP, "SVC_DROP" }, \
> + { SVC_CLOSE, "SVC_CLOSE" }, \
> + { SVC_DENIED, "SVC_DENIED" }, \
> + { SVC_PENDING, "SVC_PENDING" }, \
> + { SVC_COMPLETE, "SVC_COMPLETE" })
> +
> +TRACE_EVENT(svc_authenticate,
> + TP_PROTO(const struct svc_rqst *rqst, int auth_res, __be32 auth_stat),
> +
> + TP_ARGS(rqst, auth_res, auth_stat),
> +
> + TP_STRUCT__entry(
> + __field(u32, xid)
> + __field(unsigned long, svc_status)
> + __field(unsigned long, auth_stat)
> + ),
> +
> + TP_fast_assign(
> + __entry->xid = be32_to_cpu(rqst->rq_xid);
> + __entry->svc_status = auth_res;
> + __entry->auth_stat = be32_to_cpu(auth_stat);
> + ),
> +
> + TP_printk("xid=0x%08x auth_res=%s auth_stat=%s",
> + __entry->xid, svc_show_status(__entry->svc_status),
> + rpc_show_auth_stat(__entry->auth_stat))
> +);
> +
> TRACE_EVENT(svc_process,
> TP_PROTO(const struct svc_rqst *rqst, const char *name),
>
> diff --git a/net/sunrpc/auth_gss/gss_mech_switch.c b/net/sunrpc/auth_gss/gss_mech_switch.c
> index 8206009..30b7de6 100644
> --- a/net/sunrpc/auth_gss/gss_mech_switch.c
> +++ b/net/sunrpc/auth_gss/gss_mech_switch.c
> @@ -20,6 +20,7 @@
> #include <linux/sunrpc/sched.h>
> #include <linux/sunrpc/gss_api.h>
> #include <linux/sunrpc/clnt.h>
> +#include <trace/events/rpcgss.h>
>
> #if IS_ENABLED(CONFIG_SUNRPC_DEBUG)
> # define RPCDBG_FACILITY RPCDBG_AUTH
> @@ -158,7 +159,6 @@ struct gss_api_mech *gss_mech_get_by_OID(struct rpcsec_gss_oid *obj)
>
> if (sprint_oid(obj->data, obj->len, buf, sizeof(buf)) < 0)
> return NULL;
> - dprintk("RPC: %s(%s)\n", __func__, buf);
> request_module("rpc-auth-gss-%s", buf);
>
> rcu_read_lock();
> @@ -172,6 +172,8 @@ struct gss_api_mech *gss_mech_get_by_OID(struct rpcsec_gss_oid *obj)
> }
> }
> rcu_read_unlock();
> + if (!gm)
> + trace_rpcgss_oid_to_mech(buf);
> return gm;
> }
>
> diff --git a/net/sunrpc/auth_gss/svcauth_gss.c b/net/sunrpc/auth_gss/svcauth_gss.c
> index 8be2f20..f130990 100644
> --- a/net/sunrpc/auth_gss/svcauth_gss.c
> +++ b/net/sunrpc/auth_gss/svcauth_gss.c
> @@ -49,6 +49,9 @@
> #include <linux/sunrpc/svcauth.h>
> #include <linux/sunrpc/svcauth_gss.h>
> #include <linux/sunrpc/cache.h>
> +
> +#include <trace/events/rpcgss.h>
> +
> #include "gss_rpc_upcall.h"
>
>
> @@ -1270,9 +1273,8 @@ static int svcauth_gss_proxy_init(struct svc_rqst *rqstp,
> if (status)
> goto out;
>
> - dprintk("RPC: svcauth_gss: gss major status = %d "
> - "minor status = %d\n",
> - ud.major_status, ud.minor_status);
> + trace_rpcgss_accept_upcall(rqstp->rq_xid, ud.major_status,
> + ud.minor_status);
>
> switch (ud.major_status) {
> case GSS_S_CONTINUE_NEEDED:
> diff --git a/net/sunrpc/svc.c b/net/sunrpc/svc.c
> index d11b705..187dd4e 100644
> --- a/net/sunrpc/svc.c
> +++ b/net/sunrpc/svc.c
> @@ -1337,6 +1337,8 @@ static __printf(2,3) void svc_printk(struct svc_rqst *rqstp, const char *fmt, ..
> auth_stat = rpc_autherr_badcred;
> auth_res = progp->pg_authenticate(rqstp);
> }
> + if (auth_res != SVC_OK)
> + trace_svc_authenticate(rqstp, auth_res, auth_stat);
> switch (auth_res) {
> case SVC_OK:
> break;
> diff --git a/net/sunrpc/svcauth.c b/net/sunrpc/svcauth.c
> index 550b214..552617e 100644
> --- a/net/sunrpc/svcauth.c
> +++ b/net/sunrpc/svcauth.c
> @@ -19,6 +19,8 @@
> #include <linux/err.h>
> #include <linux/hash.h>
>
> +#include <trace/events/sunrpc.h>
> +
> #define RPCDBG_FACILITY RPCDBG_AUTH
>
>

2019-10-25 14:29:05

by Chuck Lever III

[permalink] [raw]
Subject: Re: [PATCH v1 1/2] SUNRPC: Trace gssproxy upcall results



> On Oct 24, 2019, at 11:38 AM, J. Bruce Fields <[email protected]> wrote:
>
> On Thu, Oct 24, 2019 at 09:34:10AM -0400, Chuck Lever wrote:
>> Record results of a GSS proxy ACCEPT_SEC_CONTEXT upcall and the
>> svc_authenticate() function to make field debugging of NFS server
>> Kerberos issues easier.
>
> Inclined to apply.
>
> The only thing that bugs me a bit is that this is just summarizing
> information that's passing between the kernel and userspace--so it seems
> like a job for strace or wireshark or something.

You could use those tools. However:

- strace probably isn't going to provide symbolic values for the GSS major status

- wireshark is unwieldy for initial debugging on servers with no graphics capability

The upcall trace point is built into the kernel. Flip it on and it will tell a
system administrator immediately what the upcall result was.


> --b.
>
>>
>> Signed-off-by: Chuck Lever <[email protected]>
>> Reviewed-by: Bill Baker <[email protected]>
>> ---
>> include/trace/events/rpcgss.h | 45 +++++++++++++++++++++++++++
>> include/trace/events/sunrpc.h | 55 +++++++++++++++++++++++++++++++++
>> net/sunrpc/auth_gss/gss_mech_switch.c | 4 ++
>> net/sunrpc/auth_gss/svcauth_gss.c | 8 +++--
>> net/sunrpc/svc.c | 2 +
>> net/sunrpc/svcauth.c | 2 +
>> 6 files changed, 112 insertions(+), 4 deletions(-)
>>
>> diff --git a/include/trace/events/rpcgss.h b/include/trace/events/rpcgss.h
>> index d1f7fe1..9827f53 100644
>> --- a/include/trace/events/rpcgss.h
>> +++ b/include/trace/events/rpcgss.h
>> @@ -126,6 +126,34 @@
>> DEFINE_GSSAPI_EVENT(wrap);
>> DEFINE_GSSAPI_EVENT(unwrap);
>>
>> +TRACE_EVENT(rpcgss_accept_upcall,
>> + TP_PROTO(
>> + __be32 xid,
>> + u32 major_status,
>> + u32 minor_status
>> + ),
>> +
>> + TP_ARGS(xid, major_status, minor_status),
>> +
>> + TP_STRUCT__entry(
>> + __field(u32, xid)
>> + __field(u32, minor_status)
>> + __field(unsigned long, major_status)
>> + ),
>> +
>> + TP_fast_assign(
>> + __entry->xid = be32_to_cpu(xid);
>> + __entry->minor_status = minor_status;
>> + __entry->major_status = major_status;
>> + ),
>> +
>> + TP_printk("xid=0x%08x major_status=%s (0x%08lx) minor_status=%u",
>> + __entry->xid, __entry->major_status == 0 ? "GSS_S_COMPLETE" :
>> + show_gss_status(__entry->major_status),
>> + __entry->major_status, __entry->minor_status
>> + )
>> +);
>> +
>>
>> /**
>> ** GSS auth unwrap failures
>> @@ -355,6 +383,23 @@
>> show_pseudoflavor(__entry->flavor), __entry->error)
>> );
>>
>> +TRACE_EVENT(rpcgss_oid_to_mech,
>> + TP_PROTO(
>> + const char *oid
>> + ),
>> +
>> + TP_ARGS(oid),
>> +
>> + TP_STRUCT__entry(
>> + __string(oid, oid)
>> + ),
>> +
>> + TP_fast_assign(
>> + __assign_str(oid, oid);
>> + ),
>> +
>> + TP_printk("mech for oid %s was not found", __get_str(oid))
>> +);
>>
>> #endif /* _TRACE_RPCGSS_H */
>>
>> diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h
>> index ffa3c51..c358a0a 100644
>> --- a/include/trace/events/sunrpc.h
>> +++ b/include/trace/events/sunrpc.h
>> @@ -14,6 +14,26 @@
>> #include <linux/net.h>
>> #include <linux/tracepoint.h>
>>
>> +TRACE_DEFINE_ENUM(RPC_AUTH_OK);
>> +TRACE_DEFINE_ENUM(RPC_AUTH_BADCRED);
>> +TRACE_DEFINE_ENUM(RPC_AUTH_REJECTEDCRED);
>> +TRACE_DEFINE_ENUM(RPC_AUTH_BADVERF);
>> +TRACE_DEFINE_ENUM(RPC_AUTH_REJECTEDVERF);
>> +TRACE_DEFINE_ENUM(RPC_AUTH_TOOWEAK);
>> +TRACE_DEFINE_ENUM(RPCSEC_GSS_CREDPROBLEM);
>> +TRACE_DEFINE_ENUM(RPCSEC_GSS_CTXPROBLEM);
>> +
>> +#define rpc_show_auth_stat(status) \
>> + __print_symbolic(status, \
>> + { RPC_AUTH_OK, "AUTH_OK" }, \
>> + { RPC_AUTH_BADCRED, "BADCRED" }, \
>> + { RPC_AUTH_REJECTEDCRED, "REJECTEDCRED" }, \
>> + { RPC_AUTH_BADVERF, "BADVERF" }, \
>> + { RPC_AUTH_REJECTEDVERF, "REJECTEDVERF" }, \
>> + { RPC_AUTH_TOOWEAK, "TOOWEAK" }, \
>> + { RPCSEC_GSS_CREDPROBLEM, "GSS_CREDPROBLEM" }, \
>> + { RPCSEC_GSS_CTXPROBLEM, "GSS_CTXPROBLEM" }) \
>> +
>> DECLARE_EVENT_CLASS(rpc_task_status,
>>
>> TP_PROTO(const struct rpc_task *task),
>> @@ -866,6 +886,41 @@
>> show_rqstp_flags(__entry->flags))
>> );
>>
>> +#define svc_show_status(status) \
>> + __print_symbolic(status, \
>> + { SVC_GARBAGE, "SVC_GARBAGE" }, \
>> + { SVC_SYSERR, "SVC_SYSERR" }, \
>> + { SVC_VALID, "SVC_VALID" }, \
>> + { SVC_NEGATIVE, "SVC_NEGATIVE" }, \
>> + { SVC_OK, "SVC_OK" }, \
>> + { SVC_DROP, "SVC_DROP" }, \
>> + { SVC_CLOSE, "SVC_CLOSE" }, \
>> + { SVC_DENIED, "SVC_DENIED" }, \
>> + { SVC_PENDING, "SVC_PENDING" }, \
>> + { SVC_COMPLETE, "SVC_COMPLETE" })
>> +
>> +TRACE_EVENT(svc_authenticate,
>> + TP_PROTO(const struct svc_rqst *rqst, int auth_res, __be32 auth_stat),
>> +
>> + TP_ARGS(rqst, auth_res, auth_stat),
>> +
>> + TP_STRUCT__entry(
>> + __field(u32, xid)
>> + __field(unsigned long, svc_status)
>> + __field(unsigned long, auth_stat)
>> + ),
>> +
>> + TP_fast_assign(
>> + __entry->xid = be32_to_cpu(rqst->rq_xid);
>> + __entry->svc_status = auth_res;
>> + __entry->auth_stat = be32_to_cpu(auth_stat);
>> + ),
>> +
>> + TP_printk("xid=0x%08x auth_res=%s auth_stat=%s",
>> + __entry->xid, svc_show_status(__entry->svc_status),
>> + rpc_show_auth_stat(__entry->auth_stat))
>> +);
>> +
>> TRACE_EVENT(svc_process,
>> TP_PROTO(const struct svc_rqst *rqst, const char *name),
>>
>> diff --git a/net/sunrpc/auth_gss/gss_mech_switch.c b/net/sunrpc/auth_gss/gss_mech_switch.c
>> index 8206009..30b7de6 100644
>> --- a/net/sunrpc/auth_gss/gss_mech_switch.c
>> +++ b/net/sunrpc/auth_gss/gss_mech_switch.c
>> @@ -20,6 +20,7 @@
>> #include <linux/sunrpc/sched.h>
>> #include <linux/sunrpc/gss_api.h>
>> #include <linux/sunrpc/clnt.h>
>> +#include <trace/events/rpcgss.h>
>>
>> #if IS_ENABLED(CONFIG_SUNRPC_DEBUG)
>> # define RPCDBG_FACILITY RPCDBG_AUTH
>> @@ -158,7 +159,6 @@ struct gss_api_mech *gss_mech_get_by_OID(struct rpcsec_gss_oid *obj)
>>
>> if (sprint_oid(obj->data, obj->len, buf, sizeof(buf)) < 0)
>> return NULL;
>> - dprintk("RPC: %s(%s)\n", __func__, buf);
>> request_module("rpc-auth-gss-%s", buf);
>>
>> rcu_read_lock();
>> @@ -172,6 +172,8 @@ struct gss_api_mech *gss_mech_get_by_OID(struct rpcsec_gss_oid *obj)
>> }
>> }
>> rcu_read_unlock();
>> + if (!gm)
>> + trace_rpcgss_oid_to_mech(buf);
>> return gm;
>> }
>>
>> diff --git a/net/sunrpc/auth_gss/svcauth_gss.c b/net/sunrpc/auth_gss/svcauth_gss.c
>> index 8be2f20..f130990 100644
>> --- a/net/sunrpc/auth_gss/svcauth_gss.c
>> +++ b/net/sunrpc/auth_gss/svcauth_gss.c
>> @@ -49,6 +49,9 @@
>> #include <linux/sunrpc/svcauth.h>
>> #include <linux/sunrpc/svcauth_gss.h>
>> #include <linux/sunrpc/cache.h>
>> +
>> +#include <trace/events/rpcgss.h>
>> +
>> #include "gss_rpc_upcall.h"
>>
>>
>> @@ -1270,9 +1273,8 @@ static int svcauth_gss_proxy_init(struct svc_rqst *rqstp,
>> if (status)
>> goto out;
>>
>> - dprintk("RPC: svcauth_gss: gss major status = %d "
>> - "minor status = %d\n",
>> - ud.major_status, ud.minor_status);
>> + trace_rpcgss_accept_upcall(rqstp->rq_xid, ud.major_status,
>> + ud.minor_status);
>>
>> switch (ud.major_status) {
>> case GSS_S_CONTINUE_NEEDED:
>> diff --git a/net/sunrpc/svc.c b/net/sunrpc/svc.c
>> index d11b705..187dd4e 100644
>> --- a/net/sunrpc/svc.c
>> +++ b/net/sunrpc/svc.c
>> @@ -1337,6 +1337,8 @@ static __printf(2,3) void svc_printk(struct svc_rqst *rqstp, const char *fmt, ..
>> auth_stat = rpc_autherr_badcred;
>> auth_res = progp->pg_authenticate(rqstp);
>> }
>> + if (auth_res != SVC_OK)
>> + trace_svc_authenticate(rqstp, auth_res, auth_stat);
>> switch (auth_res) {
>> case SVC_OK:
>> break;
>> diff --git a/net/sunrpc/svcauth.c b/net/sunrpc/svcauth.c
>> index 550b214..552617e 100644
>> --- a/net/sunrpc/svcauth.c
>> +++ b/net/sunrpc/svcauth.c
>> @@ -19,6 +19,8 @@
>> #include <linux/err.h>
>> #include <linux/hash.h>
>>
>> +#include <trace/events/sunrpc.h>
>> +
>> #define RPCDBG_FACILITY RPCDBG_AUTH
>>
>>

--
Chuck Lever



2019-10-28 21:24:53

by J. Bruce Fields

[permalink] [raw]
Subject: Re: [PATCH v1 1/2] SUNRPC: Trace gssproxy upcall results

On Thu, Oct 24, 2019 at 01:08:20PM -0400, Chuck Lever wrote:
>
>
> > On Oct 24, 2019, at 11:38 AM, J. Bruce Fields <[email protected]> wrote:
> >
> > On Thu, Oct 24, 2019 at 09:34:10AM -0400, Chuck Lever wrote:
> >> Record results of a GSS proxy ACCEPT_SEC_CONTEXT upcall and the
> >> svc_authenticate() function to make field debugging of NFS server
> >> Kerberos issues easier.
> >
> > Inclined to apply.
> >
> > The only thing that bugs me a bit is that this is just summarizing
> > information that's passing between the kernel and userspace--so it seems
> > like a job for strace or wireshark or something.
>
> You could use those tools. However:
>
> - strace probably isn't going to provide symbolic values for the GSS major status
>
> - wireshark is unwieldy for initial debugging on servers with no graphics capability

I don't think tcpdump, copy the file, then run wireshark, is that bad,
and there are probably ways to automate that if necessary.

The bigger problem seems to be that there's no way to do the capture:

https://unix.stackexchange.com/questions/219853/how-to-passively-capture-from-unix-domain-sockets-af-unix-socket-monitoring

I wish we could fix that somehow.

--b.

>
> The upcall trace point is built into the kernel. Flip it on and it will tell a
> system administrator immediately what the upcall result was.
>
>
> > --b.
> >
> >>
> >> Signed-off-by: Chuck Lever <[email protected]>
> >> Reviewed-by: Bill Baker <[email protected]>
> >> ---
> >> include/trace/events/rpcgss.h | 45 +++++++++++++++++++++++++++
> >> include/trace/events/sunrpc.h | 55 +++++++++++++++++++++++++++++++++
> >> net/sunrpc/auth_gss/gss_mech_switch.c | 4 ++
> >> net/sunrpc/auth_gss/svcauth_gss.c | 8 +++--
> >> net/sunrpc/svc.c | 2 +
> >> net/sunrpc/svcauth.c | 2 +
> >> 6 files changed, 112 insertions(+), 4 deletions(-)
> >>
> >> diff --git a/include/trace/events/rpcgss.h b/include/trace/events/rpcgss.h
> >> index d1f7fe1..9827f53 100644
> >> --- a/include/trace/events/rpcgss.h
> >> +++ b/include/trace/events/rpcgss.h
> >> @@ -126,6 +126,34 @@
> >> DEFINE_GSSAPI_EVENT(wrap);
> >> DEFINE_GSSAPI_EVENT(unwrap);
> >>
> >> +TRACE_EVENT(rpcgss_accept_upcall,
> >> + TP_PROTO(
> >> + __be32 xid,
> >> + u32 major_status,
> >> + u32 minor_status
> >> + ),
> >> +
> >> + TP_ARGS(xid, major_status, minor_status),
> >> +
> >> + TP_STRUCT__entry(
> >> + __field(u32, xid)
> >> + __field(u32, minor_status)
> >> + __field(unsigned long, major_status)
> >> + ),
> >> +
> >> + TP_fast_assign(
> >> + __entry->xid = be32_to_cpu(xid);
> >> + __entry->minor_status = minor_status;
> >> + __entry->major_status = major_status;
> >> + ),
> >> +
> >> + TP_printk("xid=0x%08x major_status=%s (0x%08lx) minor_status=%u",
> >> + __entry->xid, __entry->major_status == 0 ? "GSS_S_COMPLETE" :
> >> + show_gss_status(__entry->major_status),
> >> + __entry->major_status, __entry->minor_status
> >> + )
> >> +);
> >> +
> >>
> >> /**
> >> ** GSS auth unwrap failures
> >> @@ -355,6 +383,23 @@
> >> show_pseudoflavor(__entry->flavor), __entry->error)
> >> );
> >>
> >> +TRACE_EVENT(rpcgss_oid_to_mech,
> >> + TP_PROTO(
> >> + const char *oid
> >> + ),
> >> +
> >> + TP_ARGS(oid),
> >> +
> >> + TP_STRUCT__entry(
> >> + __string(oid, oid)
> >> + ),
> >> +
> >> + TP_fast_assign(
> >> + __assign_str(oid, oid);
> >> + ),
> >> +
> >> + TP_printk("mech for oid %s was not found", __get_str(oid))
> >> +);
> >>
> >> #endif /* _TRACE_RPCGSS_H */
> >>
> >> diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h
> >> index ffa3c51..c358a0a 100644
> >> --- a/include/trace/events/sunrpc.h
> >> +++ b/include/trace/events/sunrpc.h
> >> @@ -14,6 +14,26 @@
> >> #include <linux/net.h>
> >> #include <linux/tracepoint.h>
> >>
> >> +TRACE_DEFINE_ENUM(RPC_AUTH_OK);
> >> +TRACE_DEFINE_ENUM(RPC_AUTH_BADCRED);
> >> +TRACE_DEFINE_ENUM(RPC_AUTH_REJECTEDCRED);
> >> +TRACE_DEFINE_ENUM(RPC_AUTH_BADVERF);
> >> +TRACE_DEFINE_ENUM(RPC_AUTH_REJECTEDVERF);
> >> +TRACE_DEFINE_ENUM(RPC_AUTH_TOOWEAK);
> >> +TRACE_DEFINE_ENUM(RPCSEC_GSS_CREDPROBLEM);
> >> +TRACE_DEFINE_ENUM(RPCSEC_GSS_CTXPROBLEM);
> >> +
> >> +#define rpc_show_auth_stat(status) \
> >> + __print_symbolic(status, \
> >> + { RPC_AUTH_OK, "AUTH_OK" }, \
> >> + { RPC_AUTH_BADCRED, "BADCRED" }, \
> >> + { RPC_AUTH_REJECTEDCRED, "REJECTEDCRED" }, \
> >> + { RPC_AUTH_BADVERF, "BADVERF" }, \
> >> + { RPC_AUTH_REJECTEDVERF, "REJECTEDVERF" }, \
> >> + { RPC_AUTH_TOOWEAK, "TOOWEAK" }, \
> >> + { RPCSEC_GSS_CREDPROBLEM, "GSS_CREDPROBLEM" }, \
> >> + { RPCSEC_GSS_CTXPROBLEM, "GSS_CTXPROBLEM" }) \
> >> +
> >> DECLARE_EVENT_CLASS(rpc_task_status,
> >>
> >> TP_PROTO(const struct rpc_task *task),
> >> @@ -866,6 +886,41 @@
> >> show_rqstp_flags(__entry->flags))
> >> );
> >>
> >> +#define svc_show_status(status) \
> >> + __print_symbolic(status, \
> >> + { SVC_GARBAGE, "SVC_GARBAGE" }, \
> >> + { SVC_SYSERR, "SVC_SYSERR" }, \
> >> + { SVC_VALID, "SVC_VALID" }, \
> >> + { SVC_NEGATIVE, "SVC_NEGATIVE" }, \
> >> + { SVC_OK, "SVC_OK" }, \
> >> + { SVC_DROP, "SVC_DROP" }, \
> >> + { SVC_CLOSE, "SVC_CLOSE" }, \
> >> + { SVC_DENIED, "SVC_DENIED" }, \
> >> + { SVC_PENDING, "SVC_PENDING" }, \
> >> + { SVC_COMPLETE, "SVC_COMPLETE" })
> >> +
> >> +TRACE_EVENT(svc_authenticate,
> >> + TP_PROTO(const struct svc_rqst *rqst, int auth_res, __be32 auth_stat),
> >> +
> >> + TP_ARGS(rqst, auth_res, auth_stat),
> >> +
> >> + TP_STRUCT__entry(
> >> + __field(u32, xid)
> >> + __field(unsigned long, svc_status)
> >> + __field(unsigned long, auth_stat)
> >> + ),
> >> +
> >> + TP_fast_assign(
> >> + __entry->xid = be32_to_cpu(rqst->rq_xid);
> >> + __entry->svc_status = auth_res;
> >> + __entry->auth_stat = be32_to_cpu(auth_stat);
> >> + ),
> >> +
> >> + TP_printk("xid=0x%08x auth_res=%s auth_stat=%s",
> >> + __entry->xid, svc_show_status(__entry->svc_status),
> >> + rpc_show_auth_stat(__entry->auth_stat))
> >> +);
> >> +
> >> TRACE_EVENT(svc_process,
> >> TP_PROTO(const struct svc_rqst *rqst, const char *name),
> >>
> >> diff --git a/net/sunrpc/auth_gss/gss_mech_switch.c b/net/sunrpc/auth_gss/gss_mech_switch.c
> >> index 8206009..30b7de6 100644
> >> --- a/net/sunrpc/auth_gss/gss_mech_switch.c
> >> +++ b/net/sunrpc/auth_gss/gss_mech_switch.c
> >> @@ -20,6 +20,7 @@
> >> #include <linux/sunrpc/sched.h>
> >> #include <linux/sunrpc/gss_api.h>
> >> #include <linux/sunrpc/clnt.h>
> >> +#include <trace/events/rpcgss.h>
> >>
> >> #if IS_ENABLED(CONFIG_SUNRPC_DEBUG)
> >> # define RPCDBG_FACILITY RPCDBG_AUTH
> >> @@ -158,7 +159,6 @@ struct gss_api_mech *gss_mech_get_by_OID(struct rpcsec_gss_oid *obj)
> >>
> >> if (sprint_oid(obj->data, obj->len, buf, sizeof(buf)) < 0)
> >> return NULL;
> >> - dprintk("RPC: %s(%s)\n", __func__, buf);
> >> request_module("rpc-auth-gss-%s", buf);
> >>
> >> rcu_read_lock();
> >> @@ -172,6 +172,8 @@ struct gss_api_mech *gss_mech_get_by_OID(struct rpcsec_gss_oid *obj)
> >> }
> >> }
> >> rcu_read_unlock();
> >> + if (!gm)
> >> + trace_rpcgss_oid_to_mech(buf);
> >> return gm;
> >> }
> >>
> >> diff --git a/net/sunrpc/auth_gss/svcauth_gss.c b/net/sunrpc/auth_gss/svcauth_gss.c
> >> index 8be2f20..f130990 100644
> >> --- a/net/sunrpc/auth_gss/svcauth_gss.c
> >> +++ b/net/sunrpc/auth_gss/svcauth_gss.c
> >> @@ -49,6 +49,9 @@
> >> #include <linux/sunrpc/svcauth.h>
> >> #include <linux/sunrpc/svcauth_gss.h>
> >> #include <linux/sunrpc/cache.h>
> >> +
> >> +#include <trace/events/rpcgss.h>
> >> +
> >> #include "gss_rpc_upcall.h"
> >>
> >>
> >> @@ -1270,9 +1273,8 @@ static int svcauth_gss_proxy_init(struct svc_rqst *rqstp,
> >> if (status)
> >> goto out;
> >>
> >> - dprintk("RPC: svcauth_gss: gss major status = %d "
> >> - "minor status = %d\n",
> >> - ud.major_status, ud.minor_status);
> >> + trace_rpcgss_accept_upcall(rqstp->rq_xid, ud.major_status,
> >> + ud.minor_status);
> >>
> >> switch (ud.major_status) {
> >> case GSS_S_CONTINUE_NEEDED:
> >> diff --git a/net/sunrpc/svc.c b/net/sunrpc/svc.c
> >> index d11b705..187dd4e 100644
> >> --- a/net/sunrpc/svc.c
> >> +++ b/net/sunrpc/svc.c
> >> @@ -1337,6 +1337,8 @@ static __printf(2,3) void svc_printk(struct svc_rqst *rqstp, const char *fmt, ..
> >> auth_stat = rpc_autherr_badcred;
> >> auth_res = progp->pg_authenticate(rqstp);
> >> }
> >> + if (auth_res != SVC_OK)
> >> + trace_svc_authenticate(rqstp, auth_res, auth_stat);
> >> switch (auth_res) {
> >> case SVC_OK:
> >> break;
> >> diff --git a/net/sunrpc/svcauth.c b/net/sunrpc/svcauth.c
> >> index 550b214..552617e 100644
> >> --- a/net/sunrpc/svcauth.c
> >> +++ b/net/sunrpc/svcauth.c
> >> @@ -19,6 +19,8 @@
> >> #include <linux/err.h>
> >> #include <linux/hash.h>
> >>
> >> +#include <trace/events/sunrpc.h>
> >> +
> >> #define RPCDBG_FACILITY RPCDBG_AUTH
> >>
> >>
>
> --
> Chuck Lever
>
>

2019-10-30 20:35:52

by J. Bruce Fields

[permalink] [raw]
Subject: Re: [PATCH v1 1/2] SUNRPC: Trace gssproxy upcall results

On Mon, Oct 28, 2019 at 12:45:41PM -0400, Bruce Fields wrote:
> On Thu, Oct 24, 2019 at 01:08:20PM -0400, Chuck Lever wrote:
> >
> >
> > > On Oct 24, 2019, at 11:38 AM, J. Bruce Fields <[email protected]> wrote:
> > >
> > > On Thu, Oct 24, 2019 at 09:34:10AM -0400, Chuck Lever wrote:
> > >> Record results of a GSS proxy ACCEPT_SEC_CONTEXT upcall and the
> > >> svc_authenticate() function to make field debugging of NFS server
> > >> Kerberos issues easier.
> > >
> > > Inclined to apply.
> > >
> > > The only thing that bugs me a bit is that this is just summarizing
> > > information that's passing between the kernel and userspace--so it seems
> > > like a job for strace or wireshark or something.
> >
> > You could use those tools. However:
> >
> > - strace probably isn't going to provide symbolic values for the GSS major status
> >
> > - wireshark is unwieldy for initial debugging on servers with no graphics capability
>
> I don't think tcpdump, copy the file, then run wireshark, is that bad,
> and there are probably ways to automate that if necessary.
>
> The bigger problem seems to be that there's no way to do the capture:
>
> https://unix.stackexchange.com/questions/219853/how-to-passively-capture-from-unix-domain-sockets-af-unix-socket-monitoring
>
> I wish we could fix that somehow.

But, I don't know what to do about the AF_LOCAL tracing problem. Oh
well.

Applying.

--b.