diff mbox series

[v1,1/2] SUNRPC: Trace gssproxy upcall results

Message ID 20191024133410.2148.3456.stgit@klimt.1015granger.net (mailing list archive)
State New, archived
Headers show
Series [v1,1/2] SUNRPC: Trace gssproxy upcall results | expand

Commit Message

Chuck Lever Oct. 24, 2019, 1:34 p.m. UTC 
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 <chuck.lever@oracle.com>
Reviewed-by: Bill Baker <bill.baker@oracle.com>
---
 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(-)

Comments

J. Bruce Fields Oct. 24, 2019, 3:38 p.m. UTC | #1 
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 <chuck.lever@oracle.com>
> Reviewed-by: Bill Baker <bill.baker@oracle.com>
> ---
>  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 Oct. 24, 2019, 5:08 p.m. UTC | #2 
> On Oct 24, 2019, at 11:38 AM, J. Bruce Fields <bfields@fieldses.org> 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 <chuck.lever@oracle.com>
>> Reviewed-by: Bill Baker <bill.baker@oracle.com>
>> ---
>> 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
J. Bruce Fields Oct. 28, 2019, 4:45 p.m. UTC | #3 
On Thu, Oct 24, 2019 at 01:08:20PM -0400, Chuck Lever wrote:
> 
> 
> > On Oct 24, 2019, at 11:38 AM, J. Bruce Fields <bfields@fieldses.org> 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 <chuck.lever@oracle.com>
> >> Reviewed-by: Bill Baker <bill.baker@oracle.com>
> >> ---
> >> 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
> 
>
J. Bruce Fields Oct. 30, 2019, 8:34 p.m. UTC | #4 
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 <bfields@fieldses.org> 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.
diff mbox series

Patch

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