From 0c77668ddb4e7bdfbca462c6185d154d0b8889ae Mon Sep 17 00:00:00 2001 From: Chuck Lever Date: Mon, 11 Feb 2019 11:25:04 -0500 Subject: SUNRPC: Introduce trace points in rpc_auth_gss.ko Add infrastructure for trace points in the RPC_AUTH_GSS kernel module, and add a few sample trace points. These report exceptional or unexpected events, and observe the assignment of GSS sequence numbers. Signed-off-by: Chuck Lever Signed-off-by: Anna Schumaker --- include/trace/events/rpcgss.h | 361 +++++++++++++++++++++++++++++++++++++++++ include/trace/events/rpcrdma.h | 12 +- include/trace/events/sunrpc.h | 61 ++++++- 3 files changed, 431 insertions(+), 3 deletions(-) create mode 100644 include/trace/events/rpcgss.h (limited to 'include/trace') diff --git a/include/trace/events/rpcgss.h b/include/trace/events/rpcgss.h new file mode 100644 index 000000000000..d1f7fe1b6fe4 --- /dev/null +++ b/include/trace/events/rpcgss.h @@ -0,0 +1,361 @@ +/* SPDX-License-Identifier: GPL-2.0 */ +/* + * Copyright (c) 2018 Oracle. All rights reserved. + * + * Trace point definitions for the "rpcgss" subsystem. + */ + +#undef TRACE_SYSTEM +#define TRACE_SYSTEM rpcgss + +#if !defined(_TRACE_RPCRDMA_H) || defined(TRACE_HEADER_MULTI_READ) +#define _TRACE_RPCGSS_H + +#include + +/** + ** GSS-API related trace events + **/ + +TRACE_DEFINE_ENUM(GSS_S_BAD_MECH); +TRACE_DEFINE_ENUM(GSS_S_BAD_NAME); +TRACE_DEFINE_ENUM(GSS_S_BAD_NAMETYPE); +TRACE_DEFINE_ENUM(GSS_S_BAD_BINDINGS); +TRACE_DEFINE_ENUM(GSS_S_BAD_STATUS); +TRACE_DEFINE_ENUM(GSS_S_BAD_SIG); +TRACE_DEFINE_ENUM(GSS_S_NO_CRED); +TRACE_DEFINE_ENUM(GSS_S_NO_CONTEXT); +TRACE_DEFINE_ENUM(GSS_S_DEFECTIVE_TOKEN); +TRACE_DEFINE_ENUM(GSS_S_DEFECTIVE_CREDENTIAL); +TRACE_DEFINE_ENUM(GSS_S_CREDENTIALS_EXPIRED); +TRACE_DEFINE_ENUM(GSS_S_CONTEXT_EXPIRED); +TRACE_DEFINE_ENUM(GSS_S_FAILURE); +TRACE_DEFINE_ENUM(GSS_S_BAD_QOP); +TRACE_DEFINE_ENUM(GSS_S_UNAUTHORIZED); +TRACE_DEFINE_ENUM(GSS_S_UNAVAILABLE); +TRACE_DEFINE_ENUM(GSS_S_DUPLICATE_ELEMENT); +TRACE_DEFINE_ENUM(GSS_S_NAME_NOT_MN); +TRACE_DEFINE_ENUM(GSS_S_CONTINUE_NEEDED); +TRACE_DEFINE_ENUM(GSS_S_DUPLICATE_TOKEN); +TRACE_DEFINE_ENUM(GSS_S_OLD_TOKEN); +TRACE_DEFINE_ENUM(GSS_S_UNSEQ_TOKEN); +TRACE_DEFINE_ENUM(GSS_S_GAP_TOKEN); + +#define show_gss_status(x) \ + __print_flags(x, "|", \ + { GSS_S_BAD_MECH, "GSS_S_BAD_MECH" }, \ + { GSS_S_BAD_NAME, "GSS_S_BAD_NAME" }, \ + { GSS_S_BAD_NAMETYPE, "GSS_S_BAD_NAMETYPE" }, \ + { GSS_S_BAD_BINDINGS, "GSS_S_BAD_BINDINGS" }, \ + { GSS_S_BAD_STATUS, "GSS_S_BAD_STATUS" }, \ + { GSS_S_BAD_SIG, "GSS_S_BAD_SIG" }, \ + { GSS_S_NO_CRED, "GSS_S_NO_CRED" }, \ + { GSS_S_NO_CONTEXT, "GSS_S_NO_CONTEXT" }, \ + { GSS_S_DEFECTIVE_TOKEN, "GSS_S_DEFECTIVE_TOKEN" }, \ + { GSS_S_DEFECTIVE_CREDENTIAL, "GSS_S_DEFECTIVE_CREDENTIAL" }, \ + { GSS_S_CREDENTIALS_EXPIRED, "GSS_S_CREDENTIALS_EXPIRED" }, \ + { GSS_S_CONTEXT_EXPIRED, "GSS_S_CONTEXT_EXPIRED" }, \ + { GSS_S_FAILURE, "GSS_S_FAILURE" }, \ + { GSS_S_BAD_QOP, "GSS_S_BAD_QOP" }, \ + { GSS_S_UNAUTHORIZED, "GSS_S_UNAUTHORIZED" }, \ + { GSS_S_UNAVAILABLE, "GSS_S_UNAVAILABLE" }, \ + { GSS_S_DUPLICATE_ELEMENT, "GSS_S_DUPLICATE_ELEMENT" }, \ + { GSS_S_NAME_NOT_MN, "GSS_S_NAME_NOT_MN" }, \ + { GSS_S_CONTINUE_NEEDED, "GSS_S_CONTINUE_NEEDED" }, \ + { GSS_S_DUPLICATE_TOKEN, "GSS_S_DUPLICATE_TOKEN" }, \ + { GSS_S_OLD_TOKEN, "GSS_S_OLD_TOKEN" }, \ + { GSS_S_UNSEQ_TOKEN, "GSS_S_UNSEQ_TOKEN" }, \ + { GSS_S_GAP_TOKEN, "GSS_S_GAP_TOKEN" }) + + +DECLARE_EVENT_CLASS(rpcgss_gssapi_event, + TP_PROTO( + const struct rpc_task *task, + u32 maj_stat + ), + + TP_ARGS(task, maj_stat), + + TP_STRUCT__entry( + __field(unsigned int, task_id) + __field(unsigned int, client_id) + __field(u32, maj_stat) + + ), + + TP_fast_assign( + __entry->task_id = task->tk_pid; + __entry->client_id = task->tk_client->cl_clid; + __entry->maj_stat = maj_stat; + ), + + TP_printk("task:%u@%u maj_stat=%s", + __entry->task_id, __entry->client_id, + __entry->maj_stat == 0 ? + "GSS_S_COMPLETE" : show_gss_status(__entry->maj_stat)) +); + +#define DEFINE_GSSAPI_EVENT(name) \ + DEFINE_EVENT(rpcgss_gssapi_event, rpcgss_##name, \ + TP_PROTO( \ + const struct rpc_task *task, \ + u32 maj_stat \ + ), \ + TP_ARGS(task, maj_stat)) + +TRACE_EVENT(rpcgss_import_ctx, + TP_PROTO( + int status + ), + + TP_ARGS(status), + + TP_STRUCT__entry( + __field(int, status) + ), + + TP_fast_assign( + __entry->status = status; + ), + + TP_printk("status=%d", __entry->status) +); + +DEFINE_GSSAPI_EVENT(get_mic); +DEFINE_GSSAPI_EVENT(verify_mic); +DEFINE_GSSAPI_EVENT(wrap); +DEFINE_GSSAPI_EVENT(unwrap); + + +/** + ** GSS auth unwrap failures + **/ + +TRACE_EVENT(rpcgss_unwrap_failed, + TP_PROTO( + const struct rpc_task *task + ), + + TP_ARGS(task), + + TP_STRUCT__entry( + __field(unsigned int, task_id) + __field(unsigned int, client_id) + ), + + TP_fast_assign( + __entry->task_id = task->tk_pid; + __entry->client_id = task->tk_client->cl_clid; + ), + + TP_printk("task:%u@%u", __entry->task_id, __entry->client_id) +); + +TRACE_EVENT(rpcgss_bad_seqno, + TP_PROTO( + const struct rpc_task *task, + u32 expected, + u32 received + ), + + TP_ARGS(task, expected, received), + + TP_STRUCT__entry( + __field(unsigned int, task_id) + __field(unsigned int, client_id) + __field(u32, expected) + __field(u32, received) + ), + + TP_fast_assign( + __entry->task_id = task->tk_pid; + __entry->client_id = task->tk_client->cl_clid; + __entry->expected = expected; + __entry->received = received; + ), + + TP_printk("task:%u@%u expected seqno %u, received seqno %u", + __entry->task_id, __entry->client_id, + __entry->expected, __entry->received) +); + +TRACE_EVENT(rpcgss_seqno, + TP_PROTO( + const struct rpc_task *task + ), + + TP_ARGS(task), + + TP_STRUCT__entry( + __field(unsigned int, task_id) + __field(unsigned int, client_id) + __field(u32, xid) + __field(u32, seqno) + ), + + TP_fast_assign( + const struct rpc_rqst *rqst = task->tk_rqstp; + + __entry->task_id = task->tk_pid; + __entry->client_id = task->tk_client->cl_clid; + __entry->xid = be32_to_cpu(rqst->rq_xid); + __entry->seqno = rqst->rq_seqno; + ), + + TP_printk("task:%u@%u xid=0x%08x seqno=%u", + __entry->task_id, __entry->client_id, + __entry->xid, __entry->seqno) +); + +TRACE_EVENT(rpcgss_need_reencode, + TP_PROTO( + const struct rpc_task *task, + u32 seq_xmit, + bool ret + ), + + TP_ARGS(task, seq_xmit, ret), + + TP_STRUCT__entry( + __field(unsigned int, task_id) + __field(unsigned int, client_id) + __field(u32, xid) + __field(u32, seq_xmit) + __field(u32, seqno) + __field(bool, ret) + ), + + TP_fast_assign( + __entry->task_id = task->tk_pid; + __entry->client_id = task->tk_client->cl_clid; + __entry->xid = be32_to_cpu(task->tk_rqstp->rq_xid); + __entry->seq_xmit = seq_xmit; + __entry->seqno = task->tk_rqstp->rq_seqno; + __entry->ret = ret; + ), + + TP_printk("task:%u@%u xid=0x%08x rq_seqno=%u seq_xmit=%u reencode %sneeded", + __entry->task_id, __entry->client_id, + __entry->xid, __entry->seqno, __entry->seq_xmit, + __entry->ret ? "" : "un") +); + +/** + ** gssd upcall related trace events + **/ + +TRACE_EVENT(rpcgss_upcall_msg, + TP_PROTO( + const char *buf + ), + + TP_ARGS(buf), + + TP_STRUCT__entry( + __string(msg, buf) + ), + + TP_fast_assign( + __assign_str(msg, buf) + ), + + TP_printk("msg='%s'", __get_str(msg)) +); + +TRACE_EVENT(rpcgss_upcall_result, + TP_PROTO( + u32 uid, + int result + ), + + TP_ARGS(uid, result), + + TP_STRUCT__entry( + __field(u32, uid) + __field(int, result) + + ), + + TP_fast_assign( + __entry->uid = uid; + __entry->result = result; + ), + + TP_printk("for uid %u, result=%d", __entry->uid, __entry->result) +); + +TRACE_EVENT(rpcgss_context, + TP_PROTO( + unsigned long expiry, + unsigned long now, + unsigned int timeout, + unsigned int len, + const u8 *data + ), + + TP_ARGS(expiry, now, timeout, len, data), + + TP_STRUCT__entry( + __field(unsigned long, expiry) + __field(unsigned long, now) + __field(unsigned int, timeout) + __field(int, len) + __string(acceptor, data) + ), + + TP_fast_assign( + __entry->expiry = expiry; + __entry->now = now; + __entry->timeout = timeout; + __entry->len = len; + strncpy(__get_str(acceptor), data, len); + ), + + TP_printk("gc_expiry=%lu now=%lu timeout=%u acceptor=%.*s", + __entry->expiry, __entry->now, __entry->timeout, + __entry->len, __get_str(acceptor)) +); + + +/** + ** Miscellaneous events + */ + +TRACE_DEFINE_ENUM(RPC_AUTH_GSS_KRB5); +TRACE_DEFINE_ENUM(RPC_AUTH_GSS_KRB5I); +TRACE_DEFINE_ENUM(RPC_AUTH_GSS_KRB5P); + +#define show_pseudoflavor(x) \ + __print_symbolic(x, \ + { RPC_AUTH_GSS_KRB5, "RPC_AUTH_GSS_KRB5" }, \ + { RPC_AUTH_GSS_KRB5I, "RPC_AUTH_GSS_KRB5I" }, \ + { RPC_AUTH_GSS_KRB5P, "RPC_AUTH_GSS_KRB5P" }) + + +TRACE_EVENT(rpcgss_createauth, + TP_PROTO( + unsigned int flavor, + int error + ), + + TP_ARGS(flavor, error), + + TP_STRUCT__entry( + __field(unsigned int, flavor) + __field(int, error) + + ), + + TP_fast_assign( + __entry->flavor = flavor; + __entry->error = error; + ), + + TP_printk("flavor=%s error=%d", + show_pseudoflavor(__entry->flavor), __entry->error) +); + + +#endif /* _TRACE_RPCGSS_H */ + +#include diff --git a/include/trace/events/rpcrdma.h b/include/trace/events/rpcrdma.h index 399b1aedc927..962975b4313f 100644 --- a/include/trace/events/rpcrdma.h +++ b/include/trace/events/rpcrdma.h @@ -521,12 +521,18 @@ TRACE_EVENT(xprtrdma_post_send, TP_STRUCT__entry( __field(const void *, req) + __field(unsigned int, task_id) + __field(unsigned int, client_id) __field(int, num_sge) __field(int, signaled) __field(int, status) ), TP_fast_assign( + const struct rpc_rqst *rqst = &req->rl_slot; + + __entry->task_id = rqst->rq_task->tk_pid; + __entry->client_id = rqst->rq_task->tk_client->cl_clid; __entry->req = req; __entry->num_sge = req->rl_sendctx->sc_wr.num_sge; __entry->signaled = req->rl_sendctx->sc_wr.send_flags & @@ -534,9 +540,11 @@ TRACE_EVENT(xprtrdma_post_send, __entry->status = status; ), - TP_printk("req=%p, %d SGEs%s, status=%d", + TP_printk("task:%u@%u req=%p (%d SGE%s) %sstatus=%d", + __entry->task_id, __entry->client_id, __entry->req, __entry->num_sge, - (__entry->signaled ? ", signaled" : ""), + (__entry->num_sge == 1 ? "" : "s"), + (__entry->signaled ? "signaled " : ""), __entry->status ) ); diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h index 0654e9c50371..e58dda8e038c 100644 --- a/include/trace/events/sunrpc.h +++ b/include/trace/events/sunrpc.h @@ -655,9 +655,68 @@ DECLARE_EVENT_CLASS(rpc_xprt_event, DEFINE_RPC_XPRT_EVENT(timer); DEFINE_RPC_XPRT_EVENT(lookup_rqst); -DEFINE_RPC_XPRT_EVENT(transmit); DEFINE_RPC_XPRT_EVENT(complete_rqst); +TRACE_EVENT(xprt_transmit, + TP_PROTO( + const struct rpc_rqst *rqst, + int status + ), + + TP_ARGS(rqst, status), + + TP_STRUCT__entry( + __field(unsigned int, task_id) + __field(unsigned int, client_id) + __field(u32, xid) + __field(u32, seqno) + __field(int, status) + ), + + TP_fast_assign( + __entry->task_id = rqst->rq_task->tk_pid; + __entry->client_id = rqst->rq_task->tk_client->cl_clid; + __entry->xid = be32_to_cpu(rqst->rq_xid); + __entry->seqno = rqst->rq_seqno; + __entry->status = status; + ), + + TP_printk( + "task:%u@%u xid=0x%08x seqno=%u status=%d", + __entry->task_id, __entry->client_id, __entry->xid, + __entry->seqno, __entry->status) +); + +TRACE_EVENT(xprt_enq_xmit, + TP_PROTO( + const struct rpc_task *task, + int stage + ), + + TP_ARGS(task, stage), + + TP_STRUCT__entry( + __field(unsigned int, task_id) + __field(unsigned int, client_id) + __field(u32, xid) + __field(u32, seqno) + __field(int, stage) + ), + + TP_fast_assign( + __entry->task_id = task->tk_pid; + __entry->client_id = task->tk_client->cl_clid; + __entry->xid = be32_to_cpu(task->tk_rqstp->rq_xid); + __entry->seqno = task->tk_rqstp->rq_seqno; + __entry->stage = stage; + ), + + TP_printk( + "task:%u@%u xid=0x%08x seqno=%u stage=%d", + __entry->task_id, __entry->client_id, __entry->xid, + __entry->seqno, __entry->stage) +); + TRACE_EVENT(xprt_ping, TP_PROTO(const struct rpc_xprt *xprt, int status), -- cgit v1.2.3