Skip to content

Commit

Permalink
SUNRPC: Introduce trace points in rpc_auth_gss.ko
Browse files Browse the repository at this point in the history 
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 <chuck.lever@oracle.com>
Signed-off-by: Anna Schumaker <Anna.Schumaker@Netapp.com>
  • Loading branch information
Chuck Lever authored and Anna Schumaker committed Feb 14, 2019
1 parent a0584ee commit 0c77668
Show file tree
Hide file tree
Showing 7 changed files with 530 additions and 92 deletions.
361 changes: 361 additions & 0 deletions include/trace/events/rpcgss.h
View file
Original file line number Diff line number Diff line change
@@ -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 <linux/tracepoint.h>

/**
** 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 <trace/define_trace.h>
12 changes: 10 additions & 2 deletions include/trace/events/rpcrdma.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -521,22 +521,30 @@ 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 &
IB_SEND_SIGNALED;
__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
)
);
Expand Down
Loading

0 comments on commit 0c77668

Please sign in to comment.