svn rev #24118: trunk/src/ include/ include/krb5/ lib/krb5/ lib/krb5/ccache/ ...
ghudson@MIT.EDU
ghudson at MIT.EDU
Mon Jun 7 14:26:17 EDT 2010
http://src.mit.edu/fisheye/changelog/krb5/?cs=24118
Commit By: ghudson
Log Message:
ticket: 6737
subject: Trace logging
Add trace logging infrastructure code, enabled by the KRB5_TRACE
environment variable or the API functions krb5_set_trace_callback()
or krb5_set_trace_filename(). As a start, add tracing events for:
* AS-REQ client code, including FAST and preauth
* TGS-REQ client code
* AP-REQ and AP-REP code (client and server)
* sendto_kdc
* Selected ccache operations
* Selected keytab operations
Changed Files:
U trunk/src/include/cm.h
U trunk/src/include/k5-int.h
A trunk/src/include/k5-trace.h
U trunk/src/include/krb5/krb5.hin
U trunk/src/lib/krb5/ccache/ccbase.c
U trunk/src/lib/krb5/ccache/ccfns.c
U trunk/src/lib/krb5/error_tables/krb5_err.et
U trunk/src/lib/krb5/keytab/ktfns.c
U trunk/src/lib/krb5/krb/fast.c
U trunk/src/lib/krb5/krb/gc_via_tkt.c
U trunk/src/lib/krb5/krb/get_creds.c
U trunk/src/lib/krb5/krb/get_in_tkt.c
U trunk/src/lib/krb5/krb/gic_pwd.c
U trunk/src/lib/krb5/krb/init_ctx.c
U trunk/src/lib/krb5/krb/mk_rep.c
U trunk/src/lib/krb5/krb/mk_req_ext.c
U trunk/src/lib/krb5/krb/preauth2.c
U trunk/src/lib/krb5/krb/rd_rep.c
U trunk/src/lib/krb5/krb/rd_req_dec.c
U trunk/src/lib/krb5/krb/send_tgs.c
U trunk/src/lib/krb5/libkrb5.exports
U trunk/src/lib/krb5/os/Makefile.in
U trunk/src/lib/krb5/os/sendto_kdc.c
A trunk/src/lib/krb5/os/trace.c
Modified: trunk/src/include/cm.h
===================================================================
--- trunk/src/include/cm.h 2010-06-04 18:33:26 UTC (rev 24117)
+++ trunk/src/include/cm.h 2010-06-07 18:26:17 UTC (rev 24118)
@@ -60,7 +60,8 @@
krb5_error_code err;
enum conn_states state;
unsigned int is_udp : 1;
- int (*service)(struct conn_state *, struct select_state *, int);
+ int (*service)(krb5_context context, struct conn_state *,
+ struct select_state *, int);
struct addrinfo *addr;
struct {
struct {
Modified: trunk/src/include/k5-int.h
===================================================================
--- trunk/src/include/k5-int.h 2010-06-04 18:33:26 UTC (rev 24117)
+++ trunk/src/include/k5-int.h 2010-06-07 18:26:17 UTC (rev 24118)
@@ -110,6 +110,7 @@
#define INI_KRB_CCACHE "krb5cc" /* Location of the ccache */
#define INI_KRB5_CONF "krb5.ini" /* Location of krb5.conf file */
#define ANSI_STDIO
+#define DISABLE_TRACING
#endif
#include "autoconf.h"
@@ -129,6 +130,7 @@
#include "k5-platform.h"
+#include "k5-trace.h"
/* not used in krb5.h (yet) */
typedef UINT64_TYPE krb5_ui_8;
typedef INT64_TYPE krb5_int64;
@@ -1473,6 +1475,9 @@
struct _kdb_log_context *kdblog_context;
krb5_boolean allow_weak_crypto;
+
+ krb5_trace_callback trace_callback;
+ void *trace_callback_data;
};
/* could be used in a table to find an etype and initialize a block */
@@ -2869,4 +2874,10 @@
krb5_set_error_message_fl(ctx, code, __FILE__, __LINE__, __VA_ARGS__)
#endif
+#ifndef DISABLE_TRACING
+/* Do not use these functions directly; see k5-trace.h. */
+void krb5int_init_trace(krb5_context context);
+void krb5int_trace(krb5_context context, const char *fmt, ...);
+#endif
+
#endif /* _KRB5_INT_H */
Added: trunk/src/include/k5-trace.h
===================================================================
--- trunk/src/include/k5-trace.h (rev 0)
+++ trunk/src/include/k5-trace.h 2010-06-07 18:26:17 UTC (rev 24118)
@@ -0,0 +1,350 @@
+/* -*- mode: c; c-basic-offset: 4; indent-tabs-mode: nil -*- */
+/*
+ * include/k5-trace.h
+ *
+ * Copyright (C) 2010 by the Massachusetts Institute of Technology.
+ * All rights reserved.
+ *
+ * Export of this software from the United States of America may
+ * require a specific license from the United States Government.
+ * It is the responsibility of any person or organization contemplating
+ * export to obtain such a license before exporting.
+ *
+ * WITHIN THAT CONSTRAINT, permission to use, copy, modify, and
+ * distribute this software and its documentation for any purpose and
+ * without fee is hereby granted, provided that the above copyright
+ * notice appear in all copies and that both that copyright notice and
+ * this permission notice appear in supporting documentation, and that
+ * the name of M.I.T. not be used in advertising or publicity pertaining
+ * to distribution of the software without specific, written prior
+ * permission. Furthermore if you modify this software you must label
+ * your software as modified software and not distribute it in such a
+ * fashion that it might be confused with the original M.I.T. software.
+ * M.I.T. makes no representations about the suitability of
+ * this software for any purpose. It is provided "as is" without express
+ * or implied warranty.
+ *
+ *
+ * This header contains trace macro definitions, which map trace points within
+ * the code to krb5int_trace() calls with descriptive text strings.
+ *
+ * Trace logging is intended to aid power users in diagnosing configuration
+ * problems by showing what's going on behind the scenes of complex operations.
+ * Although trace logging is sometimes useful to developers, it is not intended
+ * as a replacement for a debugger, and it is not desirable to drown the user
+ * in output. Observe the following guidelines when adding trace points:
+ *
+ * - Avoid mentioning function or variable names in messages.
+ *
+ * - Try to convey what decisions are being made and what external inputs
+ * they are based on, not the process of making decisions.
+ *
+ * - It is generally not necessary to trace before returning an unrecoverable
+ * error. If an error code is unclear by itself, make it clearer with
+ * krb5_set_error_message().
+ *
+ * - Keep macros simple. Add format specifiers to krb5int_trace's formatter
+ * as necessary (and document them here) instead of transforming macro
+ * arguments.
+ *
+ * - Like printf, the trace formatter interface is not type-safe. Check your
+ * formats carefully. Cast integral arguments to the appropriate type if
+ * they do not already patch.
+ *
+ * The following specifiers are supported by the formatter (see the
+ * implementation in lib/krb5/os/trace.c for details):
+ *
+ * {int} int, in decimal
+ * {long} long, in decimal
+ * {str} const char *, display as C string
+ * {lenstr} size_t and const char *, as a counted string
+ * {hexlenstr} size_t and const char *, as hex bytes
+ * {hashlenstr} size_t and const char *, as four-character hex hash
+ * {addrinfo} struct addrinfo *, show socket type, address, port
+ * {data} krb5_data *, display as counted string
+ * {hexdata} krb5_data *, display as hex bytes
+ * {errno} int, display as number/errorstring
+ * {kerr} krb5_error_code, display as number/errorstring
+ * {keyblock} const krb5_keyblock *, display enctype and hash of key
+ * {key} krb5_key, display enctype and hash of key
+ * {cksum} const krb5_checksum *, display cksumtype and hex checksum
+ * {princ} krb5_principal, unparse and display
+ * {patypes} krb5_pa_data **, display list of padata type numbers
+ * {etype} krb5_enctype, display shortest name of enctype
+ * {etypes} krb5_enctype *, display list of enctypes
+ * {ccache} krb5_ccache, display type:name
+ * {creds} krb5_creds *, display clientprinc -> serverprinc
+ */
+
+#ifndef K5_TRACE_H
+#define K5_TRACE_H
+
+#if defined(DISABLE_TRACING)
+#define TRACE(ctx, args)
+#elif defined(_KRB5_INT_H)
+#define TRACE(ctx, args) \
+ do { if (ctx->trace_callback != NULL) krb5int_trace args; } while (0)
+#else
+/* This source file isn't using k5-int.h and doesn't know the internals of the
+ * context structure, so don't try to optimize away the call. */
+#define TRACE(ctx, args) krb5int_trace args
+#endif
+
+#define TRACE_CC_DESTROY(c, cache) \
+ TRACE(c, (c, "Destroying ccache {ccache}", cache))
+#define TRACE_CC_GEN_NEW(c, cache) \
+ TRACE(c, (c, "Generating new unique ccache based on {ccache}", cache))
+#define TRACE_CC_GET_CONFIG(c, cache, princ, key, data) \
+ TRACE(c, (c, "Read config in {ccache} for {princ}: {str}: {data}", \
+ cache, princ, key, data))
+#define TRACE_CC_INIT(c, cache, princ) \
+ TRACE(c, (c, "Initializing {ccache} with default princ {princ}", \
+ cache, princ))
+#define TRACE_CC_MOVE(c, src, dst) \
+ TRACE(c, (c, "Moving contents of ccache {src} to {dst}", src, dst))
+#define TRACE_CC_NEW_UNIQUE(c, type) \
+ TRACE(c, (c, "Resolving unique ccache of type {str}", type))
+#define TRACE_CC_REMOVE(c, cache, creds) \
+ TRACE(c, (c, "Removing {creds} from {ccache}", creds, cache))
+#define TRACE_CC_RETRIEVE(c, cache, creds, ret) \
+ TRACE(c, (c, "Retrieving {creds} from {ccache} with result: {kerr}", \
+ creds, cache, ret))
+#define TRACE_CC_RETRIEVE_REF(c, cache, creds, ret) \
+ TRACE(c, (c, "Retrying {creds} with result: {kerr}", creds, ret))
+#define TRACE_CC_SET_CONFIG(c, cache, princ, key, data) \
+ TRACE(c, (c, "Storing config in {ccache} for {princ}: {str}: {data}", \
+ cache, princ, key, data))
+#define TRACE_CC_STORE(c, cache, creds) \
+ TRACE(c, (c, "Storing {creds} in {ccache}", creds, cache))
+#define TRACE_CC_STORE_TKT(c, cache, creds) \
+ TRACE(c, (c, "Also storing {creds} based on ticket", creds))
+
+#define TRACE_FAST_ARMOR_CCACHE(c, ccache_name) \
+ TRACE(c, (c, "FAST armor ccache: {str}", ccache_name))
+#define TRACE_FAST_ARMOR_CCACHE_KEY(c, keyblock) \
+ TRACE(c, (c, "Armor ccache sesion key: {keyblock}", keyblock))
+#define TRACE_FAST_ARMOR_KEY(c, keyblock) \
+ TRACE(c, (c, "FAST armor key: {keyblock}", keyblock))
+#define TRACE_FAST_CCACHE_CONFIG(c) \
+ TRACE(c, (c, "Using FAST due to armor ccache negotiation result"))
+#define TRACE_FAST_DECODE(c) \
+ TRACE(c, (c, "Decoding FAST response"))
+#define TRACE_FAST_ENCODE(c) \
+ TRACE(c, (c, "Encoding request body and padata into FAST request"))
+#define TRACE_FAST_NEGO(c, avail) \
+ TRACE(c, (c, "FAST negotiation: {str}available", (avail) ? "" : "un"))
+#define TRACE_FAST_PADATA_UPGRADE(c) \
+ TRACE(c, (c, "Upgrading to FAST due to presence of PA_FX_FAST in reply"))
+#define TRACE_FAST_REPLY_KEY(c, keyblock) \
+ TRACE(c, (c, "FAST reply key: {keyblock}", keyblock))
+#define TRACE_FAST_REQUIRED(c) \
+ TRACE(c, (c, "Using FAST due to KRB5_FAST_REQUIRED flag"))
+
+#define TRACE_GIC_PWD_CHANGED(c) \
+ TRACE(c, (c, "Getting initial TGT with changed password"))
+#define TRACE_GIC_PWD_CHANGEPW(c, tries) \
+ TRACE(c, (c, "Attempting password change; {int} tries remaining", tries))
+#define TRACE_GIC_PWD_EXPIRED(c) \
+ TRACE(c, (c, "Principal expired; getting changepw ticket"))
+#define TRACE_GIC_PWD_MASTER(c) \
+ TRACE(c, (c, "Retrying AS request with master KDC"))
+
+#define TRACE_INIT_CREDS(c, princ) \
+ TRACE(c, (c, "Getting initial credentials for {princ}", princ))
+#define TRACE_INIT_CREDS_AS_KEY_GAK(c, keyblock) \
+ TRACE(c, (c, "AS key obtained from gak_fct: {keyblock}", keyblock))
+#define TRACE_INIT_CREDS_AS_KEY_PREAUTH(c, keyblock) \
+ TRACE(c, (c, "AS key determined by preauth: {keyblock}", keyblock))
+#define TRACE_INIT_CREDS_DECRYPTED_REPLY(c, keyblock) \
+ TRACE(c, (c, "Decrypted AS reply; session key is: {keyblock}", keyblock))
+#define TRACE_INIT_CREDS_ERROR_REPLY(c, code) \
+ TRACE(c, (c, "Received error from KDC: {kerr}", code))
+#define TRACE_INIT_CREDS_GAK(c, salt, s2kparams) \
+ TRACE(c, (c, "Getting AS key, salt \"{data}\", params \"{data}\"", \
+ salt, s2kparams))
+#define TRACE_INIT_CREDS_PREAUTH_DECRYPT_FAIL(c, code) \
+ TRACE(c, (c, "Decrypt with preauth AS key failed: {kerr}", code))
+#define TRACE_INIT_CREDS_RESTART_FAST(c) \
+ TRACE(c, (c, "Restarting to upgrade to FAST"))
+#define TRACE_INIT_CREDS_RESTART_PREAUTH_FAILED(c) \
+ TRACE(c, (c, "Restarting due to PREAUTH_FAILED from FAST negotiation"))
+#define TRACE_INIT_CREDS_REFERRAL(c, realm) \
+ TRACE(c, (c, "Following referral to realm {data}", realm))
+#define TRACE_INIT_CREDS_RETRY_TCP(c) \
+ TRACE(c, (c, "Request or response is too big for UDP; retrying with TCP"))
+#define TRACE_INIT_CREDS_SALT_PRINC(c, salt) \
+ TRACE(c, (c, "Salt derived from principal: {data}", salt))
+#define TRACE_INIT_CREDS_SERVICE(c, service) \
+ TRACE(c, (c, "Setting initial creds service to {string}", service))
+
+#define TRACE_KDC_AS_CLIENT_KEY(c, keyblock) \
+ TRACE(c, (c, "Client key: {keyblock}", keyblock))
+#define TRACE_KDC_AS_PREAUTH_REPLY_KEY(c, keyblock) \
+ TRACE(c, (c, "Reply key after preauth: {keyblock}", keyblock))
+
+#define TRACE_KT_GET_ENTRY(c, keytab, princ, vno, enctype, err) \
+ TRACE(c, (c, "Retrieving {princ} from {keytab} (vno {int}, " \
+ "enctype {etype}) with result: {kerr}", princ, keytab, \
+ (int) vno, enctype, err))
+
+#define TRACE_MK_REP(c, ctime, cusec, subkey, seqnum) \
+ TRACE(c, (c, "Creating AP-REP, time {long}.{int}, subkey {keyblock}, " \
+ "seqnum {int}", (long) ctime, (int) cusec, subkey, (int) seqnum))
+
+#define TRACE_MK_REQ(c, creds, seqnum, subkey, sesskeyblock) \
+ TRACE(c, (c, "Creating authenticator for {creds}, seqnum {int}, " \
+ "subkey {key}, session key {keyblock}", creds, (int) seqnum, \
+ subkey, sesskeyblock))
+#define TRACE_MK_REQ_ETYPES(c, etypes) \
+ TRACE(c, (c, "Negotiating for enctypes in authenticator: {etypes}", \
+ etypes))
+
+#define TRACE_PKINIT_DH_CLIENT_KEY(c, len, keybytes) \
+ TRACE(c, (c, "DH result on client: {hexlenstr}", len, keybytes))
+#define TRACE_PKINIT_DH_SERVER_KEY(c, len, keybytes) \
+ TRACE(c, (c, "DH result on KDC: {hexlenstr}", len, keybytes))
+
+#define TRACE_PREAUTH_COOKIE(c, len, data) \
+ TRACE(c, (c, "Received cookie: {lenstr}", (size_t) len, data))
+#define TRACE_PREAUTH_ENC_TS_KEY_GAK(c, keyblock) \
+ TRACE(c, (c, "AS key obtained for encrypted timestamp: {keyblock}", \
+ keyblock))
+#define TRACE_PREAUTH_ENC_TS(c, sec, usec, plain, enc) \
+ TRACE(c, (c, "Encrypted timestamp (for {long}.{int}): plain {hexdata}, " \
+ "encrypted {hexdata}", (long) sec, (int) usec, plain, enc))
+#define TRACE_PREAUTH_ETYPE_INFO(c, etype, salt, s2kparams) \
+ TRACE(c, (c, "Selected etype info: etype {etype}, salt \"{data}\", " \
+ "params \"{data}\"", etype, salt, s2kparams))
+#define TRACE_PREAUTH_INFO_FAIL(c, patype, code) \
+ TRACE(c, (c, "Preauth builtin info function failure, type={int}: {kerr}", \
+ (int) patype, code))
+#define TRACE_PREAUTH_INPUT(c, padata) \
+ TRACE(c, (c, "Processing preauth types: {patypes}", padata))
+#define TRACE_PREAUTH_OUTPUT(c, padata) \
+ TRACE(c, (c, "Produced preauth for next request: {patypes}", padata))
+#define TRACE_PREAUTH_PROCESS(c, name, patype, flags, code) \
+ TRACE(c, (c, "Preauth module {str} ({int}) (flags={int}) returned: " \
+ "{kerr}", name, (int) patype, flags, code))
+#define TRACE_PREAUTH_SAM_KEY_GAK(c, keyblock) \
+ TRACE(c, (c, "AS key obtained for SAM: {keyblock}", keyblock))
+#define TRACE_PREAUTH_SALT(c, salt, patype) \
+ TRACE(c, (c, "Received salt \"{str}\" via padata type {int}", salt, \
+ (int) patype))
+#define TRACE_PREAUTH_SKIP(c, name, patype) \
+ TRACE(c, (c, "Skipping previously used preauth module {str} ({int})", \
+ name, (int) patype))
+#define TRACE_PREAUTH_TRYAGAIN_INPUT(c, padata) \
+ TRACE(c, (c, "Preauth tryagain input types: {patypes}", padata))
+#define TRACE_PREAUTH_TRYAGAIN_OUTPUT(c, padata) \
+ TRACE(c, (c, "Followup preauth for next request: {patypes}", padata))
+
+#define TRACE_RD_REP(c, ctime, cusec, subkey, seqnum) \
+ TRACE(c, (c, "Read AP-REP, time {long}.{int}, subkey {keyblock}, " \
+ "seqnum {int}", (long) ctime, (int) cusec, subkey, (int) seqnum))
+#define TRACE_RD_REP_DCE(c, ctime, cusec, seqnum) \
+ TRACE(c, (c, "Read DCE-style AP-REP, time {long}.{int}, seqnum {int}", \
+ (long) ctime, (int) cusec, (int) seqnum))
+
+#define TRACE_RD_REQ_DECRYPT_ANY(c, princ, keyblock) \
+ TRACE(c, (c, "Decrypted AP-REQ with server principal {princ}: " \
+ "{keyblock}", princ, keyblock))
+#define TRACE_RD_REQ_DECRYPT_SPECIFIC(c, princ, keyblock) \
+ TRACE(c, (c, "Decrypted AP-REQ with specified server principal {princ}: " \
+ "{keyblock}", princ, keyblock))
+#define TRACE_RD_REQ_NEGOTIATED_ETYPE(c, etype) \
+ TRACE(c, (c, "Negotiated enctype based on authenticator: {etype}", \
+ etype))
+#define TRACE_RD_REQ_SUBKEY(c, keyblock) \
+ TRACE(c, (c, "Authenticator contains subkey: {keyblock}", keyblock))
+#define TRACE_RD_REQ_TICKET(c, client, server, keyblock) \
+ TRACE(c, (c, "AP-REQ ticket: {princ} -> {princ}, session key {keyblock}", \
+ client, server, keyblock))
+
+#define TRACE_SENDTO_KDC(c, len, rlm, master, tcp) \
+ TRACE(c, (c, "Sending request ({int} bytes) to {data}{str}{str}", len, \
+ rlm, (master) ? " (master)" : "", (tcp) ? " (tcp only)" : ""))
+#define TRACE_SENDTO_KDC_MASTER(c, master) \
+ TRACE(c, (c, "Response was{str} from master KDC", (master) ? "" : " not"))
+#define TRACE_SENDTO_KDC_RESPONSE(c, addr) \
+ TRACE(c, (c, "Received answer from {addrinfo}", addr))
+#define TRACE_SENDTO_KDC_TCP_CONNECT(c, addr) \
+ TRACE(c, (c, "Initiating TCP connection to {addrinfo}", addr))
+#define TRACE_SENDTO_KDC_TCP_DISCONNECT(c, addr) \
+ TRACE(c, (c, "Terminating TCP connection to {addrinfo}", addr))
+#define TRACE_SENDTO_KDC_TCP_ERROR_CONNECT(c, addr, err) \
+ TRACE(c, (c, "TCP error connecting to {addrinfo}: {errno}", addr, err))
+#define TRACE_SENDTO_KDC_TCP_ERROR_RECV(c, addr, err) \
+ TRACE(c, (c, "TCP error receiving from {addrinfo}: {errno}", addr, err))
+#define TRACE_SENDTO_KDC_TCP_ERROR_RECV_LEN(c, addr, err) \
+ TRACE(c, (c, "TCP error receiving from {addrinfo}: {errno}", addr, err))
+#define TRACE_SENDTO_KDC_TCP_ERROR_SEND(c, addr, err) \
+ TRACE(c, (c, "TCP error sending to {addrinfo}: {errno}", addr, err))
+#define TRACE_SENDTO_KDC_TCP_SEND(c, addr) \
+ TRACE(c, (c, "Sending TCP request to {addrinfo}", addr))
+#define TRACE_SENDTO_KDC_UDP_ERROR_RECV(c, addr, err) \
+ TRACE(c, (c, "UDP error receiving from {addrinfo}: {errno}", addr, err))
+#define TRACE_SENDTO_KDC_UDP_ERROR_SEND_INITIAL(c, addr, err) \
+ TRACE(c, (c, "UDP error sending to {addrinfo}: {errno}", addr, err))
+#define TRACE_SENDTO_KDC_UDP_ERROR_SEND_RETRY(c, addr, err) \
+ TRACE(c, (c, "UDP error sending to {addrinfo}: {errno}", addr, err))
+#define TRACE_SENDTO_KDC_UDP_SEND_INITIAL(c, addr) \
+ TRACE(c, (c, "Sending initial UDP request to {addrinfo}", addr))
+#define TRACE_SENDTO_KDC_UDP_SEND_RETRY(c, addr) \
+ TRACE(c, (c, "Sending retry UDP request to {addrinfo}", addr))
+
+#define TRACE_SEND_TGS_ETYPES(c, etypes) \
+ TRACE(c, (c, "etypes requested in TGS request: {etypes}", etypes))
+#define TRACE_SEND_TGS_SUBKEY(c, keyblock) \
+ TRACE(c, (c, "Generated subkey for TGS request: {keyblock}", keyblock))
+
+#define TRACE_TGS_REPLY(c, client, server, keyblock) \
+ TRACE(c, (c, "TGS reply is for {princ} -> {princ} with session key " \
+ "{keyblock}", client, server, keyblock))
+#define TRACE_TGS_REPLY_DECODE_SESSION(c, keyblock) \
+ TRACE(c, (c, "TGS reply didn't decode with subkey; trying session key " \
+ "({keyblock)}", keyblock))
+
+#define TRACE_TKT_CREDS(c, creds, cache) \
+ TRACE(c, (c, "Getting credentials {creds} using ccache {ccache}", \
+ creds, cache))
+#define TRACE_TKT_CREDS_ADVANCE(c, realm) \
+ TRACE(c, (c, "Received TGT for {data}; advancing current realm", realm))
+#define TRACE_TKT_CREDS_CACHED_INTERMEDIATE_TGT(c, tgt) \
+ TRACE(c, (c, "Found cached TGT for intermediate realm: {creds}", tgt))
+#define TRACE_TKT_CREDS_CACHED_SERVICE_TGT(c, tgt) \
+ TRACE(c, (c, "Found cached TGT for service realm: {creds}", tgt))
+#define TRACE_TKT_CREDS_CLOSER_REALM(c, realm) \
+ TRACE(c, (c, "Trying next closer realm in path: {data}", realm))
+#define TRACE_TKT_CREDS_COMPLETE(c, princ) \
+ TRACE(c, (c, "Received creds for desired service {princ}", princ))
+#define TRACE_TKT_CREDS_FALLBACK(c, realm) \
+ TRACE(c, (c, "Local realm referral failed; trying fallback realm {data}", \
+ realm))
+#define TRACE_TKT_CREDS_LOCAL_TGT(c, tgt) \
+ TRACE(c, (c, "Starting with TGT for client realm: {creds}", tgt))
+#define TRACE_TKT_CREDS_NON_TGT(c, princ) \
+ TRACE(c, (c, "Received non-TGT referral response ({princ}); trying " \
+ "again without referrals", princ))
+#define TRACE_TKT_CREDS_OFFPATH(c, realm) \
+ TRACE(c, (c, "Received TGT for offpath realm {data}", realm))
+#define TRACE_TKT_CREDS_REFERRAL(c, princ) \
+ TRACE(c, (c, "Following referral TGT {princ}", princ))
+#define TRACE_TKT_CREDS_REFERRAL_REALM(c, princ) \
+ TRACE(c, (c, "Server has referral realm; starting with {princ}", princ))
+#define TRACE_TKT_CREDS_RESPONSE_CODE(c, code) \
+ TRACE(c, (c, "TGS request result: {kerr}", code))
+#define TRACE_TKT_CREDS_RETRY_TCP(c) \
+ TRACE(c, (c, "Request or response is too big for UDP; retrying with TCP"))
+#define TRACE_TKT_CREDS_SERVICE_REQ(c, princ, referral) \
+ TRACE(c, (c, "Requesting tickets for {princ}, referrals {str}", princ, \
+ (referral) ? "on" : "off"))
+#define TRACE_TKT_CREDS_TARGET_TGT(c, princ) \
+ TRACE(c, (c, "Received TGT for service realm: {princ}", princ))
+#define TRACE_TKT_CREDS_TARGET_TGT_OFFPATH(c, princ) \
+ TRACE(c, (c, "Received TGT for service realm: {princ}", princ))
+#define TRACE_TKT_CREDS_TGT_REQ(c, next, cur) \
+ TRACE(c, (c, "Requesting TGT {princ} using TGT {princ}", next, cur))
+#define TRACE_TKT_CREDS_WRONG_ENCTYPE(c) \
+ TRACE(c, (c, "Retrying TGS request with desired service ticket enctypes"))
+
+#endif /* K5_TRACE_H */
Modified: trunk/src/include/krb5/krb5.hin
===================================================================
--- trunk/src/include/krb5/krb5.hin 2010-06-04 18:33:26 UTC (rev 24117)
+++ trunk/src/include/krb5/krb5.hin 2010-06-07 18:26:17 UTC (rev 24118)
@@ -2668,6 +2668,40 @@
krb5_error_code KRB5_CALLCONV
krb5_allow_weak_crypto(krb5_context context, krb5_boolean enable);
+/* This structure may be extended to contain more fields in the future. */
+struct krb5_trace_info {
+ const char *message;
+};
+
+typedef void
+(KRB5_CALLCONV *krb5_trace_callback)(krb5_context context,
+ const struct krb5_trace_info *info,
+ void *cb_data);
+
+/**
+ * Specify a callback for trace events occurring in krb5 operations performed
+ * within @a context. @a fn will be invoked with @a context as the first
+ * argument, @a cb_data as the last argument, and a pointer to a struct
+ * krb5_trace_info as the second argument. If the trace callback is reset via
+ * this function or @a context is destroyed, @a fn will be invoked with a NULL
+ * second argument to allow cleanup of @a cb_data. Supply a NULL value for @a
+ * fn to disable trace callbacks within @a context.
+ *
+ * Returns KRB5_TRACE_NOSUPP if tracing is not supported in the library (unless
+ * @a fn is NULL).
+ */
+krb5_error_code KRB5_CALLCONV
+krb5_set_trace_callback(krb5_context context, krb5_trace_callback fn,
+ void *cb_data);
+
+/**
+ * Open @a filename for appending (creating it, if necessary) and set up a
+ * callback to write trace events to it. Returns KRB5_TRACE_NOSUPP if tracing
+ * is not supported in the library.
+ */
+krb5_error_code KRB5_CALLCONV
+krb5_set_trace_filename(krb5_context context, const char *filename);
+
#if TARGET_OS_MAC
# pragma pack(pop)
#endif
Modified: trunk/src/lib/krb5/ccache/ccbase.c
===================================================================
--- trunk/src/lib/krb5/ccache/ccbase.c 2010-06-04 18:33:26 UTC (rev 24117)
+++ trunk/src/lib/krb5/ccache/ccbase.c 2010-06-07 18:26:17 UTC (rev 24118)
@@ -295,6 +295,7 @@
*id = NULL;
+ TRACE_CC_NEW_UNIQUE(context, type);
err = krb5int_cc_getops(context, type, &ops);
if (err)
return err;
@@ -373,6 +374,7 @@
krb5_error_code ret = 0;
krb5_principal princ = NULL;
+ TRACE_CC_MOVE(context, src, dst);
ret = krb5_cccol_lock(context);
if (ret) {
return ret;
Modified: trunk/src/lib/krb5/ccache/ccfns.c
===================================================================
--- trunk/src/lib/krb5/ccache/ccfns.c 2010-06-04 18:33:26 UTC (rev 24117)
+++ trunk/src/lib/krb5/ccache/ccfns.c 2010-06-07 18:26:17 UTC (rev 24118)
@@ -40,6 +40,7 @@
krb5_error_code KRB5_CALLCONV
krb5_cc_gen_new (krb5_context context, krb5_ccache *cache)
{
+ TRACE_CC_GEN_NEW(context, cache);
return (*cache)->ops->gen_new(context, cache);
}
@@ -47,12 +48,14 @@
krb5_cc_initialize(krb5_context context, krb5_ccache cache,
krb5_principal principal)
{
+ TRACE_CC_INIT(context, cache, principal);
return cache->ops->init(context, cache, principal);
}
krb5_error_code KRB5_CALLCONV
krb5_cc_destroy (krb5_context context, krb5_ccache cache)
{
+ TRACE_CC_DESTROY(context, cache);
return cache->ops->destroy(context, cache);
}
@@ -73,6 +76,7 @@
/* remove any dups */
krb5_cc_remove_cred(context, cache, KRB5_TC_MATCH_AUTHDATA, creds);
+ TRACE_CC_STORE(context, cache, creds);
ret = cache->ops->store(context, cache, creds);
if (ret) return ret;
@@ -87,6 +91,7 @@
s2 = tkt->server;
if (!krb5_principal_compare(context, s1, s2)) {
creds->server = s2;
+ TRACE_CC_STORE_TKT(context, cache, creds);
/* remove any dups */
krb5_cc_remove_cred(context, cache, KRB5_TC_MATCH_AUTHDATA, creds);
ret = cache->ops->store(context, cache, creds);
@@ -105,6 +110,7 @@
krb5_data tmprealm;
ret = cache->ops->retrieve(context, cache, flags, mcreds, creds);
+ TRACE_CC_RETRIEVE(context, cache, mcreds, ret);
if (ret != KRB5_CC_NOTFOUND)
return ret;
if (!krb5_is_referral_realm(&mcreds->server->realm))
@@ -116,6 +122,7 @@
tmprealm = mcreds->server->realm;
mcreds->server->realm = mcreds->client->realm;
ret = cache->ops->retrieve(context, cache, flags, mcreds, creds);
+ TRACE_CC_RETRIEVE_REF(context, cache, mcreds, ret);
mcreds->server->realm = tmprealm;
return ret;
}
@@ -152,6 +159,7 @@
krb5_cc_remove_cred (krb5_context context, krb5_ccache cache, krb5_flags flags,
krb5_creds *creds)
{
+ TRACE_CC_REMOVE(context, cache, creds);
return cache->ops->remove_cred(context, cache, flags, creds);
}
@@ -282,6 +290,8 @@
krb5_creds cred;
memset(&cred, 0, sizeof(cred));
+ TRACE_CC_SET_CONFIG(context, id, principal, key, data);
+
ret = build_conf_principals(context, id, principal, key, &cred);
if (ret)
goto out;
@@ -341,6 +351,8 @@
data->length = cred.ticket.length;
memcpy(data->data, cred.ticket.data, data->length);
+ TRACE_CC_GET_CONFIG(context, id, principal, key, data);
+
out:
krb5_free_cred_contents(context, &cred);
krb5_free_cred_contents(context, &mcred);
Modified: trunk/src/lib/krb5/error_tables/krb5_err.et
===================================================================
--- trunk/src/lib/krb5/error_tables/krb5_err.et 2010-06-04 18:33:26 UTC (rev 24117)
+++ trunk/src/lib/krb5/error_tables/krb5_err.et 2010-06-07 18:26:17 UTC (rev 24118)
@@ -351,4 +351,6 @@
error_code KRB5_LOCAL_ADDR_REQUIRED, "Auth context must contain local address"
error_code KRB5_REMOTE_ADDR_REQUIRED, "Auth context must contain remote address"
+
+error_code KRB5_TRACE_NOSUPP, "Tracing unsupported"
end
Modified: trunk/src/lib/krb5/keytab/ktfns.c
===================================================================
--- trunk/src/lib/krb5/keytab/ktfns.c 2010-06-04 18:33:26 UTC (rev 24117)
+++ trunk/src/lib/krb5/keytab/ktfns.c 2010-06-07 18:26:17 UTC (rev 24118)
@@ -72,6 +72,7 @@
}
err = krb5_x((keytab)->ops->get,(context, keytab, principal, vno, enctype,
entry));
+ TRACE_KT_GET_ENTRY(context, keytab, principal, vno, enctype, err);
if (principal == &princ_data)
krb5_free_default_realm(context, princ_data.realm.data);
return err;
Modified: trunk/src/lib/krb5/krb/fast.c
===================================================================
--- trunk/src/lib/krb5/krb/fast.c 2010-06-04 18:33:26 UTC (rev 24117)
+++ trunk/src/lib/krb5/krb/fast.c 2010-06-07 18:26:17 UTC (rev 24118)
@@ -69,10 +69,12 @@
retval = krb5_cc_get_principal(context, ccache, &creds.client);
if (retval == 0)
retval = krb5_get_credentials(context, 0, ccache, &creds, &out_creds);
- if (retval == 0)
+ if (retval == 0) {
+ TRACE_FAST_ARMOR_CCACHE_KEY(context, &out_creds->keyblock);
retval = krb5_mk_req_extended(context, &authcontext,
AP_OPTS_USE_SUBKEY, NULL /*data*/,
out_creds, &encoded_authenticator);
+ }
if (retval == 0)
retval = krb5_auth_con_getsendsubkey(context, authcontext, &subkey);
if (retval == 0)
@@ -80,6 +82,7 @@
&out_creds->keyblock, "ticketarmor",
&armor_key);
if (retval == 0) {
+ TRACE_FAST_ARMOR_KEY(context, armor_key);
armor = calloc(1, sizeof(krb5_fast_armor));
if (armor == NULL)
retval = ENOMEM;
@@ -148,6 +151,7 @@
krb5_clear_error_message(context);
target_realm = krb5_princ_realm(context, request->server);
if (opte->opt_private->fast_ccache_name) {
+ TRACE_FAST_ARMOR_CCACHE(context, opte->opt_private->fast_ccache_name);
state->fast_state_flags |= KRB5INT_FAST_ARMOR_AVAIL;
retval = krb5_cc_resolve(context, opte->opt_private->fast_ccache_name,
&ccache);
@@ -160,13 +164,17 @@
config_data.data = NULL;
retval = krb5_cc_get_config(context, ccache, target_principal,
KRB5_CONF_FAST_AVAIL, &config_data);
- if ((retval == 0) && config_data.data )
+ if ((retval == 0) && config_data.data) {
+ TRACE_FAST_CCACHE_CONFIG(context);
state->fast_state_flags |= KRB5INT_FAST_DO_FAST;
+ }
krb5_free_data_contents(context, &config_data);
retval = 0;
}
- if (opte->opt_private->fast_flags& KRB5_FAST_REQUIRED)
+ if (opte->opt_private->fast_flags & KRB5_FAST_REQUIRED) {
+ TRACE_FAST_REQUIRED(context);
state->fast_state_flags |= KRB5INT_FAST_DO_FAST;
+ }
if (retval == 0 && (state->fast_state_flags & KRB5INT_FAST_DO_FAST)) {
retval = fast_armor_ap_request(context, state, ccache,
target_principal);
@@ -215,6 +223,8 @@
if (state->armor_key == NULL) {
return encoder(request, encoded_request);
}
+
+ TRACE_FAST_ENCODE(context);
/* Fill in a fresh random nonce for each inner request*/
random_data.length = 4;
random_data.data = (char *)random_buf;
@@ -302,6 +312,7 @@
fx_reply = krb5int_find_pa_data(context, in_padata, KRB5_PADATA_FX_FAST);
if (fx_reply == NULL)
retval = KRB5_ERR_FAST_REQUIRED;
+ TRACE_FAST_DECODE(context);
if (retval == 0) {
scratch.data = (char *) fx_reply->contents;
scratch.length = fx_reply->length;
@@ -530,6 +541,7 @@
"strengthenkey", existing_key,
"replykey", &key);
if (retval == 0) {
+ TRACE_FAST_REPLY_KEY(context, key);
*out_key = *key;
free(key);
}
@@ -621,6 +633,7 @@
*fast_avail = (pa != NULL);
}
}
+ TRACE_FAST_NEGO(context, *fast_avail);
if (checksum)
krb5_free_checksum(context, checksum);
return retval;
@@ -636,6 +649,7 @@
if (!(state->fast_state_flags & KRB5INT_FAST_ARMOR_AVAIL))
return FALSE;
if (krb5int_find_pa_data(context, padata, KRB5_PADATA_FX_FAST) != NULL) {
+ TRACE_FAST_PADATA_UPGRADE(context);
state->fast_state_flags |= KRB5INT_FAST_DO_FAST;
return TRUE;
}
Modified: trunk/src/lib/krb5/krb/gc_via_tkt.c
===================================================================
--- trunk/src/lib/krb5/krb/gc_via_tkt.c 2010-06-04 18:33:26 UTC (rev 24117)
+++ trunk/src/lib/krb5/krb/gc_via_tkt.c 2010-06-07 18:26:17 UTC (rev 24118)
@@ -55,6 +55,8 @@
pkdcrep->enc_part2->session,
&(*ppcreds)->keyblock)))
goto cleanup;
+ TRACE_TGS_REPLY(context, (*ppcreds)->client, (*ppcreds)->server,
+ &(*ppcreds)->keyblock);
if ((retval = krb5_copy_data(context, psectkt, &pdata)))
goto cleanup_keyblock;
@@ -295,6 +297,7 @@
KRB5_KEYUSAGE_TGS_REP_ENCPART_SUBKEY,
&dec_rep);
if (retval) {
+ TRACE_TGS_REPLY_DECODE_SESSION(context, &tkt->keyblock);
if ((krb5int_decode_tgs_rep(context, response_data,
&tkt->keyblock,
KRB5_KEYUSAGE_TGS_REP_ENCPART_SESSKEY, &dec_rep)) == 0)
Modified: trunk/src/lib/krb5/krb/get_creds.c
===================================================================
--- trunk/src/lib/krb5/krb/get_creds.c 2010-06-04 18:33:26 UTC (rev 24117)
+++ trunk/src/lib/krb5/krb/get_creds.c 2010-06-07 18:26:17 UTC (rev 24118)
@@ -301,6 +301,8 @@
if (code != 0)
return code;
+ TRACE_TKT_CREDS_TGT_REQ(context, ctx->tgt_princ, ctx->cur_tgt->server);
+
/* Construct input creds using ctx->tgt_in_creds as a container. */
memset(&ctx->tgt_in_creds, 0, sizeof(ctx->tgt_in_creds));
ctx->tgt_in_creds.client = ctx->client;
@@ -321,6 +323,8 @@
krb5_error_code code;
int extra_options;
+ TRACE_TKT_CREDS_SERVICE_REQ(context, ctx->server, referral);
+
/* Include the caller-specified KDC options in service requests. */
extra_options = ctx->req_kdcopt;
@@ -372,6 +376,7 @@
/* Depending on our state, we may or may not be able to handle an error.
* For now, store it in the context and return success. */
+ TRACE_TKT_CREDS_RESPONSE_CODE(context, code);
ctx->reply_code = code;
return 0;
}
@@ -421,6 +426,8 @@
{
krb5_error_code code;
+ TRACE_TKT_CREDS_COMPLETE(context, ctx->reply_creds->server);
+
/* Note the authdata we asked for in the output creds. */
ctx->reply_creds->authdata = ctx->authdata;
ctx->authdata = NULL;
@@ -505,6 +512,7 @@
krb5_free_data_contents(context, &ctx->server->realm);
ctx->server->realm = string2data(hrealms[0]);
free(hrealms);
+ TRACE_TKT_CREDS_FALLBACK(context, ctx->server->realm);
/* Obtain a TGT for the new service realm. */
ctx->getting_tgt_for = STATE_NON_REFERRAL;
@@ -542,17 +550,20 @@
ctx->server)) {
/* We got the ticket we asked for... but we didn't necessarily ask for
* it with the right enctypes. Try a non-referral request if so. */
- if (wrong_enctype(context, ctx->reply_creds->keyblock.enctype))
+ if (wrong_enctype(context, ctx->reply_creds->keyblock.enctype)) {
+ TRACE_TKT_CREDS_WRONG_ENCTYPE(context);
return begin_non_referral(context, ctx);
+ }
- /* Note the authdata we asked for in the output creds. */
return complete(context, ctx);
}
/* Old versions of Active Directory can rewrite the server name instead of
* returning a referral. Try a non-referral query if we see this. */
- if (!IS_TGS_PRINC(context, ctx->reply_creds->server))
+ if (!IS_TGS_PRINC(context, ctx->reply_creds->server)) {
+ TRACE_TKT_CREDS_NON_TGT(context, ctx->reply_creds->server);
return begin_non_referral(context, ctx);
+ }
if (ctx->referral_count == 1) {
/* Cache the referral TGT only if it's from the local realm.
@@ -587,6 +598,7 @@
krb5_free_creds(context, ctx->cur_tgt);
ctx->cur_tgt = ctx->reply_creds;
ctx->reply_creds = NULL;
+ TRACE_TKT_CREDS_REFERRAL(context, ctx->cur_tgt->server);
/* Rewrite the server realm to be the referral realm. */
krb5_free_data_contents(context, &ctx->server->realm);
@@ -672,6 +684,7 @@
if (data_eq(*tgt_realm, ctx->server->realm)) {
/* We received the server realm TGT we asked for. */
+ TRACE_TKT_CREDS_TARGET_TGT_OFFPATH(context, ctx->cur_tgt->server);
return end_get_tgt(context, ctx);
} else if (ctx->offpath_count++ >= KRB5_REFERRAL_MAXHOPS) {
/* Time to give up. */
@@ -845,6 +858,7 @@
return code;
if (cached_tgt != NULL) {
/* Advance the current realm and keep going. */
+ TRACE_TKT_CREDS_CACHED_INTERMEDIATE_TGT(context, cached_tgt);
krb5_free_creds(context, ctx->cur_tgt);
ctx->cur_tgt = cached_tgt;
if (ctx->next_realm == ctx->last_realm)
@@ -874,6 +888,7 @@
* ctx->cur_realm, so it's time to give up. */
return ctx->reply_code;
}
+ TRACE_TKT_CREDS_CLOSER_REALM(context, ctx->next_realm);
} else {
/* Verify that we got a TGT. */
if (!IS_TGS_PRINC(context, ctx->reply_creds->server))
@@ -899,9 +914,11 @@
return code;
if (path_realm == ctx->last_realm) {
/* We received a TGT for the target realm. */
+ TRACE_TKT_CREDS_TARGET_TGT(context, ctx->cur_tgt->server);
return end_get_tgt(context, ctx);
} else if (path_realm != NULL) {
/* We still have further to go; advance the traversal. */
+ TRACE_TKT_CREDS_ADVANCE(context, tgt_realm);
ctx->cur_realm = path_realm;
ctx->next_realm = ctx->last_realm;
}
@@ -910,6 +927,7 @@
return KRB5_KDCREP_MODIFIED;
} else {
/* We went off the path; start the off-path chase. */
+ TRACE_TKT_CREDS_OFFPATH(context, tgt_realm);
return begin_get_tgt_offpath(context, ctx);
}
}
@@ -938,6 +956,7 @@
if (code != 0)
return code;
if (cached_tgt != NULL) {
+ TRACE_TKT_CREDS_CACHED_SERVICE_TGT(context, cached_tgt);
krb5_free_creds(context, ctx->cur_tgt);
ctx->cur_tgt = cached_tgt;
return end_get_tgt(context, ctx);
@@ -951,6 +970,7 @@
return code;
if (ctx->cur_tgt == NULL)
return ctx->cache_code;
+ TRACE_TKT_CREDS_LOCAL_TGT(context, ctx->cur_tgt);
/* Initialize the realm path. */
code = init_realm_path(context, ctx);
@@ -1024,6 +1044,7 @@
krb5_free_data_contents(context, &ctx->server->realm);
code = krb5int_copy_data_contents(context, &ctx->client->realm,
&ctx->server->realm);
+ TRACE_TKT_CREDS_REFERRAL_REALM(context, ctx->server);
if (code != 0)
return code;
}
@@ -1043,6 +1064,7 @@
krb5_error_code code;
krb5_tkt_creds_context ctx = NULL;
+ TRACE_TKT_CREDS(context, in_creds, ccache);
ctx = k5alloc(sizeof(*ctx), &code);
if (ctx == NULL)
goto cleanup;
@@ -1140,9 +1162,10 @@
/* Get the next request and realm. Turn on TCP if necessary. */
code = krb5_tkt_creds_step(context, ctx, &reply, &request, &realm,
&flags);
- if (code == KRB5KRB_ERR_RESPONSE_TOO_BIG && !tcp_only)
+ if (code == KRB5KRB_ERR_RESPONSE_TOO_BIG && !tcp_only) {
+ TRACE_TKT_CREDS_RETRY_TCP(context);
tcp_only = 1;
- else if (code != 0 || !(flags & KRB5_TKT_CREDS_STEP_FLAG_CONTINUE))
+ } else if (code != 0 || !(flags & KRB5_TKT_CREDS_STEP_FLAG_CONTINUE))
break;
krb5_free_data_contents(context, &reply);
Modified: trunk/src/lib/krb5/krb/get_in_tkt.c
===================================================================
--- trunk/src/lib/krb5/krb/get_in_tkt.c 2010-06-04 18:33:26 UTC (rev 24117)
+++ trunk/src/lib/krb5/krb/get_in_tkt.c 2010-06-07 18:26:17 UTC (rev 24118)
@@ -557,9 +557,10 @@
&request,
&realm,
&flags);
- if (code == KRB5KRB_ERR_RESPONSE_TOO_BIG && !tcp_only)
+ if (code == KRB5KRB_ERR_RESPONSE_TOO_BIG && !tcp_only) {
+ TRACE_INIT_CREDS_RETRY_TCP(context);
tcp_only = 1;
- else if (code != 0 || !(flags & KRB5_INIT_CREDS_STEP_FLAG_CONTINUE))
+ } else if (code != 0 || !(flags & KRB5_INIT_CREDS_STEP_FLAG_CONTINUE))
break;
krb5_free_data_contents(context, &reply);
@@ -787,6 +788,8 @@
char *str = NULL;
krb5_gic_opt_ext *opte;
+ TRACE_INIT_CREDS(context, client);
+
ctx = k5alloc(sizeof(*ctx), &code);
if (code != 0)
goto cleanup;
@@ -985,6 +988,8 @@
{
char *s;
+ TRACE_INIT_CREDS_SERVICE(context, service);
+
s = strdup(service);
if (s == NULL)
return ENOMEM;
@@ -1018,6 +1023,8 @@
assert(error != NULL);
+ TRACE_INIT_CREDS_ERROR_REPLY(context,
+ error->error + ERROR_TABLE_BASE_krb5);
if (error->error == KRB_ERR_RESPONSE_TOO_BIG) {
krb5_free_error(context, error);
return KRB5KRB_ERR_RESPONSE_TOO_BIG;
@@ -1199,12 +1206,18 @@
negotiation_requests_restart(krb5_context context, krb5_init_creds_context ctx,
krb5_pa_data **padata)
{
- if (!ctx->have_restarted &&
- (krb5int_upgrade_to_fast_p(context, ctx->fast_state, padata) ||
- (ctx->err_reply->error == KDC_ERR_PREAUTH_FAILED &&
- !ctx->sent_nontrivial_preauth)))
- return 1;
- return 0;
+ if (ctx->have_restarted)
+ return FALSE;
+ if (krb5int_upgrade_to_fast_p(context, ctx->fast_state, padata)) {
+ TRACE_INIT_CREDS_RESTART_FAST(context);
+ return TRUE;
+ }
+ if (ctx->err_reply->error == KDC_ERR_PREAUTH_FAILED &&
+ !ctx->sent_nontrivial_preauth) {
+ TRACE_INIT_CREDS_RESTART_PREAUTH_FAILED(context);
+ return TRUE;
+ }
+ return FALSE;
}
/* Ensure that the reply enctype was among the requested enctypes. */
@@ -1278,6 +1291,7 @@
code = KRB5KDC_ERR_WRONG_REALM;
goto cleanup;
}
+ TRACE_INIT_CREDS_REFERRAL(context, &ctx->err_reply->client->realm);
/* Rewrite request.client with realm from error reply */
krb5_free_data_contents(context, &ctx->request->client->realm);
code = krb5int_copy_data_contents(context,
@@ -1360,6 +1374,7 @@
*/
if (ctx->salt.length == SALT_TYPE_AFS_LENGTH && ctx->salt.data == NULL) {
code = krb5_principal2salt(context, ctx->reply->client, &ctx->salt);
+ TRACE_INIT_CREDS_SALT_PRINC(context, &ctx->salt);
if (code != 0)
goto cleanup;
}
@@ -1377,16 +1392,20 @@
as_key at all yet, then use the gak_fct to get one, and try
again. */
if (ctx->as_key.length) {
+ TRACE_INIT_CREDS_AS_KEY_PREAUTH(context, &ctx->as_key);
code = krb5int_fast_reply_key(context, strengthen_key, &ctx->as_key,
&encrypting_key);
if (code != 0)
goto cleanup;
code = decrypt_as_reply(context, NULL, ctx->reply, &encrypting_key);
+ if (code != 0)
+ TRACE_INIT_CREDS_PREAUTH_DECRYPT_FAIL(context, code);
} else
code = -1;
if (code != 0) {
/* if we haven't get gotten a key, get it now */
+ TRACE_INIT_CREDS_GAK(context, &ctx->salt, &ctx->s2kparams);
code = (*ctx->gak_fct)(context, ctx->request->client,
ctx->reply->enc_part.enctype,
ctx->prompter, ctx->prompter_data,
@@ -1394,6 +1413,7 @@
&ctx->as_key, ctx->gak_data);
if (code != 0)
goto cleanup;
+ TRACE_INIT_CREDS_AS_KEY_GAK(context, &ctx->as_key);
code = krb5int_fast_reply_key(context, strengthen_key, &ctx->as_key,
&encrypting_key);
@@ -1405,6 +1425,8 @@
goto cleanup;
}
+ TRACE_INIT_CREDS_DECRYPTED_REPLY(context, ctx->reply->enc_part2->session);
+
code = krb5int_fast_verify_nego(context, ctx->fast_state,
ctx->reply, ctx->encoded_previous_request,
&encrypting_key, &fast_avail);
Modified: trunk/src/lib/krb5/krb/gic_pwd.c
===================================================================
--- trunk/src/lib/krb5/krb/gic_pwd.c 2010-06-04 18:33:26 UTC (rev 24117)
+++ trunk/src/lib/krb5/krb/gic_pwd.c 2010-06-07 18:26:17 UTC (rev 24118)
@@ -173,6 +173,7 @@
the master kdc */
if (!use_master) {
+ TRACE_GIC_PWD_MASTER(context);
use_master = 1;
if (as_reply) {
@@ -220,6 +221,7 @@
*/
if (options && !(options->flags & KRB5_GET_INIT_CREDS_OPT_CHG_PWD_PRMPT))
goto cleanup;
+ TRACE_GIC_PWD_EXPIRED(context);
/* ok, we have an expired password. Give the user a few chances
to change it */
@@ -255,6 +257,7 @@
sizeof(banner));
for (tries = 3; tries; tries--) {
+ TRACE_GIC_PWD_CHANGEPW(context, tries);
pw0.length = sizeof(pw0array);
pw1.length = sizeof(pw1array);
@@ -326,6 +329,7 @@
from the master. this is the last try. the return from this
is final. */
+ TRACE_GIC_PWD_CHANGED(context);
ret = krb5int_get_init_creds(context, creds, client, prompter, data,
start_time, in_tkt_service, options,
krb5_get_as_key_password, (void *) &pw0,
Modified: trunk/src/lib/krb5/krb/init_ctx.c
===================================================================
--- trunk/src/lib/krb5/krb/init_ctx.c 2010-06-04 18:33:26 UTC (rev 24117)
+++ trunk/src/lib/krb5/krb/init_ctx.c 2010-06-07 18:26:17 UTC (rev 24118)
@@ -234,8 +234,12 @@
ctx->fcc_default_format = tmp + 0x0500;
ctx->prompt_types = 0;
ctx->use_conf_ktypes = 0;
-
ctx->udp_pref_limit = -1;
+ ctx->trace_callback = NULL;
+#ifndef DISABLE_TRACING
+ if (!secure)
+ krb5int_init_trace(ctx);
+#endif
*context = ctx;
return 0;
@@ -264,6 +268,11 @@
krb5_clear_error_message(ctx);
+#ifndef DISABLE_TRACING
+ if (ctx->trace_callback)
+ ctx->trace_callback(ctx, NULL, ctx->trace_callback_data);
+#endif
+
ctx->magic = 0;
free(ctx);
}
Modified: trunk/src/lib/krb5/krb/mk_rep.c
===================================================================
--- trunk/src/lib/krb5/krb/mk_rep.c 2010-06-04 18:33:26 UTC (rev 24117)
+++ trunk/src/lib/krb5/krb/mk_rep.c 2010-06-07 18:26:17 UTC (rev 24118)
@@ -113,6 +113,9 @@
else
repl.seq_number = auth_context->local_seq_number;
+ TRACE_MK_REP(context, repl.ctime, repl.cusec, repl.subkey,
+ repl.seq_number);
+
/* encode it before encrypting */
if ((retval = encode_krb5_ap_rep_enc_part(&repl, &scratch)))
return retval;
Modified: trunk/src/lib/krb5/krb/mk_req_ext.c
===================================================================
--- trunk/src/lib/krb5/krb/mk_req_ext.c 2010-06-04 18:33:26 UTC (rev 24117)
+++ trunk/src/lib/krb5/krb/mk_req_ext.c 2010-06-07 18:26:17 UTC (rev 24118)
@@ -135,10 +135,11 @@
/* generate seq number if needed */
if ((((*auth_context)->auth_context_flags & KRB5_AUTH_CONTEXT_DO_SEQUENCE)
|| ((*auth_context)->auth_context_flags & KRB5_AUTH_CONTEXT_RET_SEQUENCE))
- && ((*auth_context)->local_seq_number == 0))
+ && ((*auth_context)->local_seq_number == 0)) {
if ((retval = krb5_generate_seq_number(context, &in_creds->keyblock,
&(*auth_context)->local_seq_number)))
goto cleanup;
+ }
/* generate subkey if needed */
if ((ap_req_options & AP_OPTS_USE_SUBKEY)&&(!(*auth_context)->send_subkey)) {
@@ -201,6 +202,8 @@
desired_etypes = (*auth_context)->permitted_etypes;
}
+ TRACE_MK_REQ(context, in_creds, (*auth_context)->local_seq_number,
+ (*auth_context)->send_subkey, &in_creds->keyblock);
if ((retval = generate_authenticator(context,
(*auth_context)->authentp,
in_creds->client, checksump,
@@ -305,6 +308,7 @@
/* Only send EtypeList if we prefer another enctype to tkt_enctype */
if (desired_etypes != NULL && desired_etypes[0] != tkt_enctype) {
+ TRACE_MK_REQ_ETYPES(context, desired_etypes);
retval = make_etype_list(context, desired_etypes, tkt_enctype,
&authent->authorization_data);
if (retval)
Modified: trunk/src/lib/krb5/krb/preauth2.c
===================================================================
--- trunk/src/lib/krb5/krb/preauth2.c 2010-06-04 18:33:26 UTC (rev 24117)
+++ trunk/src/lib/krb5/krb/preauth2.c 2010-06-07 18:26:17 UTC (rev 24118)
@@ -540,10 +540,7 @@
/* if it's a REAL module, try to call it only once per library call */
if (module_required_flags & PA_REAL) {
if (module->use_count > 0) {
-#ifdef DEBUG
- fprintf(stderr, "skipping already-used module \"%s\"(%d)\n",
- module->name, module->pa_type);
-#endif
+ TRACE_PREAUTH_SKIP(kcontext, module->name, module->pa_type);
continue;
}
module->use_count++;
@@ -568,6 +565,8 @@
gak_fct, gak_data, salt, s2kparams,
as_key,
&out_pa_data);
+ TRACE_PREAUTH_PROCESS(kcontext, module->name, module->pa_type,
+ module->flags, ret);
/* Make note of the module's flags and status. */
*module_flags = module->flags;
*module_ret = ret;
@@ -613,6 +612,7 @@
if (retval)
return retval;
+ TRACE_PREAUTH_SALT(context, salt, in_padata->pa_type);
if (in_padata->pa_type == KRB5_PADATA_AFS3_SALT)
salt->length = SALT_TYPE_AFS_LENGTH;
@@ -629,6 +629,8 @@
{
krb5_pa_data *pa = calloc(1, sizeof(krb5_pa_data));
krb5_octet *contents;
+
+ TRACE_PREAUTH_COOKIE(context, in_padata->length, in_padata->contents);
if (pa == NULL)
return ENOMEM;
contents = malloc(in_padata->length);
@@ -671,6 +673,7 @@
prompter, prompter_data,
salt, s2kparams, as_key, gak_data))))
return(ret);
+ TRACE_PREAUTH_ENC_TS_KEY_GAK(context, as_key);
}
/* now get the time of day, and encrypt it accordingly */
@@ -681,20 +684,11 @@
if ((ret = encode_krb5_pa_enc_ts(&pa_enc, &tmp)))
return(ret);
-#ifdef DEBUG
- fprintf (stderr, "key type %d bytes %02x %02x ...\n",
- as_key->enctype,
- as_key->contents[0], as_key->contents[1]);
-#endif
ret = krb5_encrypt_helper(context, as_key,
KRB5_KEYUSAGE_AS_REQ_PA_ENC_TS,
tmp, &enc_data);
-#ifdef DEBUG
- fprintf (stderr, "enc data { type=%d kvno=%d data=%02x %02x ... }\n",
- enc_data.enctype, enc_data.kvno,
- 0xff & enc_data.ciphertext.data[0],
- 0xff & enc_data.ciphertext.data[1]);
-#endif
+ TRACE_PREAUTH_ENC_TS(context, pa_enc.patimestamp, pa_enc.pausec,
+ tmp, &enc_data.ciphertext);
krb5_free_data(context, tmp);
@@ -831,6 +825,7 @@
krb5_free_sam_challenge(context, sam_challenge);
return(ret);
}
+ TRACE_PREAUTH_SAM_KEY_GAK(context, as_key);
}
snprintf(name, sizeof(name), "%.*s",
SAMDATA(sam_challenge->sam_type_name, "SAM Authentication",
@@ -1789,6 +1784,8 @@
return KRB5KRB_ERR_GENERIC;
}
+ TRACE_PREAUTH_TRYAGAIN_INPUT(kcontext, padata);
+
for (i = 0; padata[i] != NULL && padata[i]->pa_type != 0; i++) {
out_padata = NULL;
for (j = 0; j < context->n_modules; j++) {
@@ -1820,6 +1817,7 @@
grow_pa_list(return_padata, &out_pa_list_size,
out_padata, k);
free(out_padata);
+ TRACE_PREAUTH_TRYAGAIN_OUTPUT(kcontext, *return_padata);
return 0;
}
}
@@ -1857,16 +1855,7 @@
return(0);
}
-#ifdef DEBUG
- fprintf (stderr, "salt len=%d", (int) salt->length);
- if ((int) salt->length > 0)
- fprintf (stderr, " '%.*s'", salt->length, salt->data);
- fprintf (stderr, "; preauth data types:");
- for (i = 0; in_padata[i]; i++) {
- fprintf (stderr, " %d", in_padata[i]->pa_type);
- }
- fprintf (stderr, "\n");
-#endif
+ TRACE_PREAUTH_INPUT(context, in_padata);
out_pa_list = NULL;
out_pa_list_size = 0;
@@ -1961,16 +1950,7 @@
&etype_info[l]->s2kparams,
s2kparams)) != 0)
goto cleanup;
-#ifdef DEBUG
- for (j = 0; etype_info[j]; j++) {
- krb5_etype_info_entry *e = etype_info[j];
- fprintf (stderr, "etype info %d: etype %d salt len=%d",
- j, e->etype, e->length);
- if (e->length > 0 && e->length != KRB5_ETYPE_NO_SALT)
- fprintf (stderr, " '%.*s'", e->length, e->salt);
- fprintf (stderr, "\n");
- }
-#endif
+ TRACE_PREAUTH_ETYPE_INFO(context, *etype, salt, s2kparams);
break;
}
case KRB5_PADATA_PW_SALT:
@@ -1997,12 +1977,9 @@
prompter, prompter_data,
gak_fct, gak_data)))) {
if (paorder[h] == PA_INFO) {
-#ifdef DEBUG
- fprintf (stderr,
- "internal function for type %d, flag %d "
- "failed with err %d\n",
- in_padata[i]->pa_type, paorder[h], ret);
-#endif
+ TRACE_PREAUTH_INFO_FAIL(context,
+ in_padata[i]->pa_type,
+ ret);
ret = 0;
continue; /* PA_INFO type failed, ignore */
}
@@ -2059,6 +2036,7 @@
}
}
+ TRACE_PREAUTH_OUTPUT(context, out_pa_list);
*out_padata = out_pa_list;
if (etype_info)
krb5_free_etype_info(context, etype_info);
Modified: trunk/src/lib/krb5/krb/rd_rep.c
===================================================================
--- trunk/src/lib/krb5/krb/rd_rep.c 2010-06-04 18:33:26 UTC (rev 24117)
+++ trunk/src/lib/krb5/krb/rd_rep.c 2010-06-07 18:26:17 UTC (rev 24118)
@@ -133,6 +133,9 @@
/* Get remote sequence number. */
auth_context->remote_seq_number = enc->seq_number;
+ TRACE_RD_REP(context, enc->ctime, enc->cusec, enc->subkey,
+ enc->seq_number);
+
*repl = enc;
enc = NULL;
@@ -192,6 +195,8 @@
goto clean_scratch;
}
+ TRACE_RD_REP_DCE(context, repl->ctime, repl->cusec, repl->seq_number);
+
clean_scratch:
memset(scratch.data, 0, scratch.length);
Modified: trunk/src/lib/krb5/krb/rd_req_dec.c
===================================================================
--- trunk/src/lib/krb5/krb/rd_req_dec.c 2010-06-04 18:33:26 UTC (rev 24117)
+++ trunk/src/lib/krb5/krb/rd_req_dec.c 2010-06-07 18:26:17 UTC (rev 24118)
@@ -97,6 +97,10 @@
req->ticket->enc_part.enctype, &ktent);
if (retval == 0) {
retval = krb5_decrypt_tkt_part(context, &ktent.key, req->ticket);
+ if (retval == 0) {
+ TRACE_RD_REQ_DECRYPT_SPECIFIC(context, ktent.principal,
+ &ktent.key);
+ }
if (retval == 0 && key != NULL)
retval = krb5_copy_keyblock_contents(context, &ktent.key, key);
@@ -125,6 +129,7 @@
if (retval == 0) {
krb5_principal tmp = NULL;
+ TRACE_RD_REQ_DECRYPT_ANY(context, ktent.principal, &ktent.key);
/*
* We overwrite ticket->server to be the principal
* that we match in the keytab. The reason for doing
@@ -248,6 +253,8 @@
check_valid_flag ? &decrypt_key : NULL)))
goto cleanup;
}
+ TRACE_RD_REQ_TICKET(context, req->ticket->enc_part2->client,
+ req->ticket->server, req->ticket->enc_part2->session);
/* XXX this is an evil hack. check_valid_flag is set iff the call
is not from inside the kdc. we can use this to determine which
@@ -471,11 +478,13 @@
&(*auth_context)->negotiated_etype);
if (retval != 0)
goto cleanup;
+ TRACE_RD_REQ_NEGOTIATED_ETYPE(context, (*auth_context)->negotiated_etype);
assert((*auth_context)->negotiated_etype != ENCTYPE_NULL);
(*auth_context)->remote_seq_number = (*auth_context)->authentp->seq_number;
if ((*auth_context)->authentp->subkey) {
+ TRACE_RD_REQ_SUBKEY(context, (*auth_context)->authentp->subkey);
if ((retval = krb5_k_create_key(context,
(*auth_context)->authentp->subkey,
&((*auth_context)->recv_subkey))))
Modified: trunk/src/lib/krb5/krb/send_tgs.c
===================================================================
--- trunk/src/lib/krb5/krb/send_tgs.c 2010-06-04 18:33:26 UTC (rev 24117)
+++ trunk/src/lib/krb5/krb/send_tgs.c 2010-06-07 18:26:17 UTC (rev 24118)
@@ -211,6 +211,7 @@
if ((retval = krb5_generate_subkey( context, &in_cred->keyblock,
&local_subkey)) != 0)
return retval;
+ TRACE_SEND_TGS_SUBKEY(context, local_subkey);
if (authorization_data) {
/* need to encrypt it in the request */
@@ -241,6 +242,7 @@
krb5_get_tgs_ktypes(context, sname, &(tgsreq.ktype));
for(tgsreq.nktypes = 0; tgsreq.ktype[tgsreq.nktypes]; tgsreq.nktypes++);
}
+ TRACE_SEND_TGS_ETYPES(context, tgsreq.ktype);
if (second_ticket) {
if ((retval = decode_krb5_ticket(second_ticket, &sec_ticket)))
Modified: trunk/src/lib/krb5/libkrb5.exports
===================================================================
--- trunk/src/lib/krb5/libkrb5.exports 2010-06-04 18:33:26 UTC (rev 24117)
+++ trunk/src/lib/krb5/libkrb5.exports 2010-06-07 18:26:17 UTC (rev 24118)
@@ -587,9 +587,11 @@
krb5int_free_data_list
krb5int_get_authdata_containee_types
krb5int_init_context_kdc
+krb5int_init_trace
krb5int_initialize_library
krb5int_pac_sign
krb5int_sendtokdc_debug_handler
+krb5int_trace
profile_abandon
profile_add_relation
profile_clear_relation
Modified: trunk/src/lib/krb5/os/Makefile.in
===================================================================
--- trunk/src/lib/krb5/os/Makefile.in 2010-06-04 18:33:26 UTC (rev 24117)
+++ trunk/src/lib/krb5/os/Makefile.in 2010-06-07 18:26:17 UTC (rev 24118)
@@ -50,6 +50,7 @@
thread_safe.o \
timeofday.o \
toffset.o \
+ trace.o \
unlck_file.o \
ustime.o \
write_msg.o
@@ -93,6 +94,7 @@
$(OUTPRE)thread_safe.$(OBJEXT) \
$(OUTPRE)timeofday.$(OBJEXT) \
$(OUTPRE)toffset.$(OBJEXT) \
+ $(OUTPRE)trace.$(OBJEXT) \
$(OUTPRE)unlck_file.$(OBJEXT) \
$(OUTPRE)ustime.$(OBJEXT) \
$(OUTPRE)write_msg.$(OBJEXT)
@@ -136,6 +138,7 @@
$(srcdir)/thread_safe.c \
$(srcdir)/timeofday.c \
$(srcdir)/toffset.c \
+ $(srcdir)/trace.c \
$(srcdir)/unlck_file.c \
$(srcdir)/ustime.c \
$(srcdir)/write_msg.c
Modified: trunk/src/lib/krb5/os/sendto_kdc.c
===================================================================
--- trunk/src/lib/krb5/os/sendto_kdc.c 2010-06-04 18:33:26 UTC (rev 24117)
+++ trunk/src/lib/krb5/os/sendto_kdc.c 2010-06-07 18:26:17 UTC (rev 24118)
@@ -371,6 +371,7 @@
dprint("krb5_sendto_kdc(%d@%p, \"%D\", use_master=%d, tcp_only=%d)\n",
message->length, message->data, realm, *use_master, tcp_only);
+ TRACE_SENDTO_KDC(context, message->length, realm, *use_master, tcp_only);
if (!tcp_only && context->udp_pref_limit < 0) {
int tmp;
@@ -442,6 +443,7 @@
*use_master = 1;
krb5int_free_addrlist (&addrs3);
}
+ TRACE_SENDTO_KDC_MASTER(context, *use_master);
}
krb5int_free_addrlist (&addrs);
return 0;
@@ -575,10 +577,10 @@
return 0;
}
-static int service_tcp_fd (struct conn_state *conn,
- struct select_state *selstate, int ssflags);
-static int service_udp_fd (struct conn_state *conn,
- struct select_state *selstate, int ssflags);
+static int service_tcp_fd(krb5_context context, struct conn_state *conn,
+ struct select_state *selstate, int ssflags);
+static int service_udp_fd(krb5_context context, struct conn_state *conn,
+ struct select_state *selstate, int ssflags);
static void
set_conn_state_msg_length (struct conn_state *state, const krb5_data *message)
@@ -649,10 +651,10 @@
}
static int
-start_connection (struct conn_state *state,
- struct select_state *selstate,
- struct sendto_callback_info* callback_info,
- krb5_data* callback_buffer)
+start_connection(krb5_context context, struct conn_state *state,
+ struct select_state *selstate,
+ struct sendto_callback_info *callback_info,
+ krb5_data *callback_buffer)
{
int fd, e;
struct addrinfo *ai = state->addr;
@@ -683,6 +685,7 @@
dperror("sendto_kdc: ioctl(FIONBIO)");
if (setsockopt(fd, SOL_SOCKET, SO_LINGER, &lopt, sizeof(lopt)))
dperror("sendto_kdc: setsockopt(SO_LINGER)");
+ TRACE_SENDTO_KDC_TCP_CONNECT(context, ai);
}
/* Start connecting to KDC. */
@@ -705,10 +708,9 @@
}
} else {
/*
- * Connect returned zero even though we tried to make it
- * non-blocking, which should have caused it to return before
- * finishing the connection. Oh well. Someone's network
- * stack is broken, but if they gave us a connection, use it.
+ * Connect returned zero even though we made it non-blocking. This
+ * happens normally for UDP sockets, and can perhaps also happen for
+ * TCP sockets connecting to localhost.
*/
state->state = WRITING;
state->fd = fd;
@@ -747,9 +749,11 @@
ssize_t ret;
sg_buf *sg = &state->x.out.sgbuf[0];
+ TRACE_SENDTO_KDC_UDP_SEND_INITIAL(context, ai);
dprint("sending %d bytes on fd %d\n", SG_LEN(sg), state->fd);
ret = send(state->fd, SG_BUF(sg), SG_LEN(sg), 0);
if (ret < 0 || (size_t) ret != SG_LEN(sg)) {
+ TRACE_SENDTO_KDC_UDP_ERROR_SEND_INITIAL(context, ai, SOCKET_ERRNO);
dperror("sendto");
(void) closesocket(state->fd);
state->fd = INVALID_SOCKET;
@@ -793,10 +797,10 @@
Otherwise, the caller should immediately move on to process the
next connection. */
static int
-maybe_send (struct conn_state *conn,
- struct select_state *selstate,
- struct sendto_callback_info* callback_info,
- krb5_data* callback_buffer)
+maybe_send(krb5_context context, struct conn_state *conn,
+ struct select_state *selstate,
+ struct sendto_callback_info *callback_info,
+ krb5_data *callback_buffer)
{
sg_buf *sg;
ssize_t ret;
@@ -804,8 +808,10 @@
dprint("maybe_send(@%p) state=%s type=%s\n", conn,
state_strings[conn->state],
conn->is_udp ? "udp" : "tcp");
- if (conn->state == INITIALIZING)
- return start_connection(conn, selstate, callback_info, callback_buffer);
+ if (conn->state == INITIALIZING) {
+ return start_connection(context, conn, selstate, callback_info,
+ callback_buffer);
+ }
/* Did we already shut down this channel? */
if (conn->state == FAILED) {
@@ -820,12 +826,14 @@
return -1;
}
- /* UDP - Send message, possibly for the first time, possibly a
- retransmit if a previous attempt timed out. */
+ /* UDP - retransmit after a previous attempt timed out. */
sg = &conn->x.out.sgbuf[0];
+ TRACE_SENDTO_KDC_UDP_SEND_RETRY(context, conn->addr);
dprint("sending %d bytes on fd %d\n", SG_LEN(sg), conn->fd);
ret = send(conn->fd, SG_BUF(sg), SG_LEN(sg), 0);
if (ret < 0 || (size_t) ret != SG_LEN(sg)) {
+ TRACE_SENDTO_KDC_UDP_ERROR_SEND_INITIAL(context, conn->addr,
+ SOCKET_ERRNO);
dperror("send");
/* Keep connection alive, we'll try again next pass.
@@ -883,10 +891,10 @@
or the socket has closed and no others are open. */
static int
-service_tcp_fd (struct conn_state *conn, struct select_state *selstate,
- int ssflags)
+service_tcp_fd(krb5_context context, struct conn_state *conn,
+ struct select_state *selstate, int ssflags)
{
- krb5_error_code e = 0;
+ int e = 0;
ssize_t nwritten, nread;
if (!(ssflags & (SSF_READ|SSF_WRITE|SSF_EXCEPTION)))
@@ -899,6 +907,7 @@
/* Bad -- the KDC shouldn't be sending to us first. */
e = EINVAL /* ?? */;
kill_conn:
+ TRACE_SENDTO_KDC_TCP_DISCONNECT(context, conn->addr);
kill_conn(conn, selstate, e);
if (e == EINVAL) {
closesocket(conn->fd);
@@ -927,6 +936,7 @@
*/
e = get_so_error(conn->fd);
if (e) {
+ TRACE_SENDTO_KDC_TCP_ERROR_CONNECT(context, conn->addr, e);
dprint("socket error on write fd: %m", e);
goto kill_conn;
}
@@ -948,10 +958,12 @@
((conn->x.out.sg_count == 2 ? SG_LEN(&conn->x.out.sgp[1]) : 0)
+ SG_LEN(&conn->x.out.sgp[0])),
conn->fd);
+ TRACE_SENDTO_KDC_TCP_SEND(context, conn->addr);
nwritten = SOCKET_WRITEV(conn->fd, conn->x.out.sgp,
conn->x.out.sg_count, tmp);
if (nwritten < 0) {
e = SOCKET_ERRNO;
+ TRACE_SENDTO_KDC_TCP_ERROR_SEND(context, conn->addr, e);
dprint("failed: %m\n", e);
goto kill_conn;
}
@@ -1006,6 +1018,7 @@
e = nread ? SOCKET_ERRNO : ECONNRESET;
free(conn->x.in.buf);
conn->x.in.buf = 0;
+ TRACE_SENDTO_KDC_TCP_ERROR_RECV(context, conn->addr, e);
goto kill_conn;
}
conn->x.in.n_left -= nread;
@@ -1020,6 +1033,7 @@
conn->x.in.bufsizebytes + conn->x.in.bufsizebytes_read,
4 - conn->x.in.bufsizebytes_read);
if (nread < 0) {
+ TRACE_SENDTO_KDC_TCP_ERROR_RECV_LEN(context, conn->addr, e);
e = SOCKET_ERRNO;
goto kill_conn;
}
@@ -1052,8 +1066,8 @@
}
static int
-service_udp_fd(struct conn_state *conn, struct select_state *selstate,
- int ssflags)
+service_udp_fd(krb5_context context, struct conn_state *conn,
+ struct select_state *selstate, int ssflags)
{
int nread;
@@ -1064,6 +1078,7 @@
nread = recv(conn->fd, conn->x.in.buf, conn->x.in.bufsize, 0);
if (nread < 0) {
+ TRACE_SENDTO_KDC_UDP_ERROR_RECV(context, conn->addr, SOCKET_ERRNO);
kill_conn(conn, selstate, SOCKET_ERRNO);
return 0;
}
@@ -1120,7 +1135,7 @@
conns[i].fd, conns[i].addr,
state_strings[(int) conns[i].state]);
- if (conns[i].service (&conns[i], selstate, ssflags)) {
+ if (conns[i].service(context, &conns[i], selstate, ssflags)) {
int stop = 1;
if (msg_handler != NULL) {
@@ -1246,9 +1261,7 @@
dprint("host %d\n", host);
/* Send to the host, wait for a response, then move on. */
- if (maybe_send(&conns[host],
- sel_state,
- callback_info,
+ if (maybe_send(context, &conns[host], sel_state, callback_info,
(callback_info ? &callback_data[host] : NULL)))
continue;
@@ -1297,6 +1310,7 @@
goto egress;
}
/* Success! */
+ TRACE_SENDTO_KDC_RESPONSE(context, conns[winning_conn].addr);
reply->data = conns[winning_conn].x.in.buf;
reply->length = (conns[winning_conn].x.in.pos
- conns[winning_conn].x.in.buf);
Added: trunk/src/lib/krb5/os/trace.c
===================================================================
--- trunk/src/lib/krb5/os/trace.c (rev 0)
+++ trunk/src/lib/krb5/os/trace.c 2010-06-07 18:26:17 UTC (rev 24118)
@@ -0,0 +1,368 @@
+/* -*- mode: c; indent-tabs-mode: nil -*- */
+/*
+ * lib/krb5/krb/trace.c
+ *
+ * Copyright 2009 by the Massachusetts Institute of Technology.
+ * All Rights Reserved.
+ *
+ * Export of this software from the United States of America may
+ * require a specific license from the United States Government.
+ * It is the responsibility of any person or organization contemplating
+ * export to obtain such a license before exporting.
+ *
+ * WITHIN THAT CONSTRAINT, permission to use, copy, modify, and
+ * distribute this software and its documentation for any purpose and
+ * without fee is hereby granted, provided that the above copyright
+ * notice appear in all copies and that both that copyright notice and
+ * this permission notice appear in supporting documentation, and that
+ * the name of M.I.T. not be used in advertising or publicity pertaining
+ * to distribution of the software without specific, written prior
+ * permission. Furthermore if you modify this software you must label
+ * your software as modified software and not distribute it in such a
+ * fashion that it might be confused with the original M.I.T. software.
+ * M.I.T. makes no representations about the suitability of
+ * this software for any purpose. It is provided "as is" without express
+ * or implied warranty.
+ *
+ * k5trace implementation
+ */
+
+/* k5trace is defined in k5-int.h as a macro or static inline function,
+ * and is called like so:
+ *
+ * void k5trace(krb5_context context, const char *fmt, ...)
+ *
+ * Arguments may or may not be evaluated, so don't pass argument
+ * expressions with side effects. Tracing support and calls can be
+ * explicitly compiled out with DISABLE_TRACING, but compile-time
+ * support is enabled by default. Tracing calls use a custom
+ * formatter supporting the following format specifications:
+ */
+
+#include "k5-int.h"
+
+#ifndef DISABLE_TRACING
+
+static void subfmt(krb5_context context, struct k5buf *buf,
+ const char *fmt, ...);
+
+/* Return a four-byte hex string from the first two bytes of a SHA-1 hash of a
+ * byte array. Return NULL on failure. */
+static char *
+hash_bytes(krb5_context context, const void *ptr, size_t len)
+{
+ krb5_checksum cksum;
+ krb5_data d = make_data((void *) ptr, len);
+ char *s = NULL;
+
+ if (krb5_k_make_checksum(context, CKSUMTYPE_NIST_SHA, NULL, 0, &d,
+ &cksum) != 0)
+ return NULL;
+ if (cksum.length >= 2)
+ (void) asprintf(&s, "%02X%02X", cksum.contents[0], cksum.contents[1]);
+ krb5_free_checksum_contents(context, &cksum);
+ return s;
+}
+
+static char *
+trace_format(krb5_context context, const char *fmt, va_list ap)
+{
+ struct k5buf buf;
+ krb5_error_code kerr;
+ size_t len;
+ int err;
+ unsigned int i;
+ struct addrinfo *ai;
+ const krb5_data *d;
+ krb5_data data;
+ char addrbuf[NI_MAXHOST], portbuf[NI_MAXSERV], tmpbuf[200], *str;
+ const char *p;
+ krb5_const_principal princ;
+ const krb5_keyblock *keyblock;
+ krb5_key key;
+ const krb5_checksum *cksum;
+ krb5_pa_data **padata;
+ krb5_ccache ccache;
+ krb5_keytab keytab;
+ krb5_creds *creds;
+ krb5_enctype *etypes, etype;
+
+ krb5int_buf_init_dynamic(&buf);
+ while (TRUE) {
+ /* Advance to the next word in braces. */
+ len = strcspn(fmt, "{");
+ krb5int_buf_add_len(&buf, fmt, len);
+ if (fmt[len] == '\0')
+ break;
+ fmt += len + 1;
+ len = strcspn(fmt, "}");
+ if (fmt[len] == '\0' || len > sizeof(tmpbuf) - 1)
+ break;
+ memcpy(tmpbuf, fmt, len);
+ tmpbuf[len] = '\0';
+ fmt += len + 1;
+
+ /* Process the format word. */
+ if (strcmp(tmpbuf, "int") == 0) {
+ krb5int_buf_add_fmt(&buf, "%d", va_arg(ap, int));
+ } else if (strcmp(tmpbuf, "long") == 0) {
+ krb5int_buf_add_fmt(&buf, "%ld", va_arg(ap, long));
+ } else if (strcmp(tmpbuf, "str") == 0) {
+ p = va_arg(ap, const char *);
+ krb5int_buf_add(&buf, (p == NULL) ? "(null)" : p);
+ } else if (strcmp(tmpbuf, "lenstr") == 0) {
+ len = va_arg(ap, size_t);
+ p = va_arg(ap, const char *);
+ if (p == NULL && len != 0)
+ krb5int_buf_add(&buf, "(null)");
+ else
+ krb5int_buf_add_len(&buf, p, len);
+ } else if (strcmp(tmpbuf, "hexlenstr") == 0) {
+ len = va_arg(ap, size_t);
+ p = va_arg(ap, const char *);
+ if (p == NULL && len != 0)
+ krb5int_buf_add(&buf, "(null)");
+ else {
+ for (i = 0; i < len; i++)
+ krb5int_buf_add_fmt(&buf, "%02X", (unsigned char) p[i]);
+ }
+ } else if (strcmp(tmpbuf, "hashlenstr") == 0) {
+ len = va_arg(ap, size_t);
+ p = va_arg(ap, const char *);
+ if (p == NULL && len != 0)
+ krb5int_buf_add(&buf, "(null)");
+ else {
+ str = hash_bytes(context, p, len);
+ if (str != NULL)
+ krb5int_buf_add(&buf, str);
+ free(str);
+ }
+ } else if (strcmp(tmpbuf, "addrinfo") == 0) {
+ ai = va_arg(ap, struct addrinfo *);
+ if (ai->ai_socktype == SOCK_DGRAM)
+ krb5int_buf_add(&buf, "dgram");
+ else if (ai->ai_socktype == SOCK_STREAM)
+ krb5int_buf_add(&buf, "stream");
+ else
+ krb5int_buf_add_fmt(&buf, "socktype%d", ai->ai_socktype);
+
+ if (getnameinfo(ai->ai_addr, ai->ai_addrlen,
+ addrbuf, sizeof(addrbuf), portbuf, sizeof(portbuf),
+ NI_NUMERICHOST|NI_NUMERICSERV) != 0) {
+ if (ai->ai_addr->sa_family == AF_UNSPEC)
+ krb5int_buf_add(&buf, " AF_UNSPEC");
+ else
+ krb5int_buf_add_fmt(&buf, " af%d", ai->ai_addr->sa_family);
+ } else
+ krb5int_buf_add_fmt(&buf, " %s:%s", addrbuf, portbuf);
+ } else if (strcmp(tmpbuf, "data") == 0) {
+ d = va_arg(ap, krb5_data *);
+ if (d == NULL || (d->length != 0 && d->data == NULL))
+ krb5int_buf_add(&buf, "(null)");
+ else
+ krb5int_buf_add_len(&buf, d->data, d->length);
+ } else if (strcmp(tmpbuf, "hexdata") == 0) {
+ d = va_arg(ap, krb5_data *);
+ if (d == NULL)
+ krb5int_buf_add(&buf, "(null)");
+ else
+ subfmt(context, &buf, "{hexlenstr}", d->length, d->data);
+ } else if (strcmp(tmpbuf, "errno") == 0) {
+ err = va_arg(ap, int);
+ p = NULL;
+#ifdef HAVE_STRERROR_R
+ if (strerror_r(err, tmpbuf, sizeof(tmpbuf)) == 0)
+ p = tmpbuf;
+#endif
+ if (p == NULL)
+ p = strerror(err);
+ krb5int_buf_add_fmt(&buf, "%d/%s", err, p);
+ } else if (strcmp(tmpbuf, "kerr") == 0) {
+ kerr = va_arg(ap, krb5_error_code);
+ p = krb5_get_error_message(context, kerr);
+ krb5int_buf_add_fmt(&buf, "%ld/%s", (long) kerr,
+ (kerr == 0) ? "success" : p);
+ krb5_free_error_message(context, p);
+ } else if (strcmp(tmpbuf, "keyblock") == 0) {
+ keyblock = va_arg(ap, const krb5_keyblock *);
+ if (keyblock == NULL)
+ krb5int_buf_add(&buf, "(null)");
+ else {
+ subfmt(context, &buf, "{etype}/{hashlenstr}",
+ keyblock->enctype, keyblock->length,
+ keyblock->contents);
+ }
+ } else if (strcmp(tmpbuf, "key") == 0) {
+ key = va_arg(ap, krb5_key);
+ if (key == NULL)
+ krb5int_buf_add(&buf, "(null");
+ else
+ subfmt(context, &buf, "{keyblock}", &key->keyblock);
+ } else if (strcmp(tmpbuf, "cksum") == 0) {
+ cksum = va_arg(ap, const krb5_checksum *);
+ data = make_data(cksum->contents, cksum->length);
+ subfmt(context, &buf, "{int}/{hexdata}",
+ (int) cksum->checksum_type, &data);
+ } else if (strcmp(tmpbuf, "princ") == 0) {
+ princ = va_arg(ap, krb5_principal);
+ if (krb5_unparse_name(context, princ, &str) == 0) {
+ krb5int_buf_add(&buf, str);
+ krb5_free_unparsed_name(context, str);
+ }
+ } else if (strcmp(tmpbuf, "patypes") == 0) {
+ padata = va_arg(ap, krb5_pa_data **);
+ if (padata == NULL || *padata == NULL)
+ krb5int_buf_add(&buf, "(empty)");
+ for (; padata != NULL && *padata != NULL; padata++) {
+ krb5int_buf_add_fmt(&buf, "%d", (int) (*padata)->pa_type);
+ if (*(padata + 1) != NULL)
+ krb5int_buf_add(&buf, ", ");
+ }
+ } else if (strcmp(tmpbuf, "etype") == 0) {
+ etype = va_arg(ap, krb5_enctype);
+ if (krb5_enctype_to_name(etype, TRUE, tmpbuf, sizeof(tmpbuf)) == 0)
+ krb5int_buf_add(&buf, tmpbuf);
+ else
+ krb5int_buf_add_fmt(&buf, "%d", (int) etype);
+ } else if (strcmp(tmpbuf, "etypes") == 0) {
+ etypes = va_arg(ap, krb5_enctype *);
+ if (etypes == NULL || *etypes == 0)
+ krb5int_buf_add(&buf, "(empty");
+ for (; etypes != NULL && *etypes != 0; etypes++) {
+ subfmt(context, &buf, "{etype}", *etypes);
+ if (*(etypes + 1) != 0)
+ krb5int_buf_add(&buf, ", ");
+ }
+ } else if (strcmp(tmpbuf, "ccache") == 0) {
+ ccache = va_arg(ap, krb5_ccache);
+ krb5int_buf_add(&buf, krb5_cc_get_type(context, ccache));
+ krb5int_buf_add(&buf, ":");
+ krb5int_buf_add(&buf, krb5_cc_get_name(context, ccache));
+ } else if (strcmp(tmpbuf, "keytab") == 0) {
+ keytab = va_arg(ap, krb5_keytab);
+ if (krb5_kt_get_name(context, keytab, tmpbuf, sizeof(tmpbuf)) == 0)
+ krb5int_buf_add(&buf, tmpbuf);
+ } else if (strcmp(tmpbuf, "creds") == 0) {
+ creds = va_arg(ap, krb5_creds *);
+ subfmt(context, &buf, "{princ} -> {princ}",
+ creds->client, creds->server);
+ }
+ }
+ return krb5int_buf_data(&buf);
+}
+
+/* Allows trace_format formatters to be represented in terms of other
+ * formatters. */
+static void
+subfmt(krb5_context context, struct k5buf *buf, const char *fmt, ...)
+{
+ va_list ap;
+ char *str;
+
+ va_start(ap, fmt);
+ str = trace_format(context, fmt, ap);
+ if (str != NULL)
+ krb5int_buf_add(buf, str);
+ free(str);
+ va_end(ap);
+}
+
+void
+krb5int_init_trace(krb5_context context)
+{
+ const char *filename;
+
+ filename = getenv("KRB5_TRACE");
+ if (filename)
+ (void) krb5_set_trace_filename(context, filename);
+}
+
+void
+krb5int_trace(krb5_context context, const char *fmt, ...)
+{
+ va_list ap;
+ struct krb5_trace_info info;
+ char *str = NULL, *msg = NULL;
+ krb5_int32 sec, usec;
+
+ va_start(ap, fmt);
+ if (context == NULL || context->trace_callback == NULL)
+ return;
+ str = trace_format(context, fmt, ap);
+ if (str == NULL)
+ goto cleanup;
+ if (krb5_crypto_us_timeofday(&sec, &usec) != 0)
+ goto cleanup;
+ if (asprintf(&msg, "[%d] %d.%d: %s\n", (int) getpid(), (int) sec,
+ (int) usec, str) < 0)
+ goto cleanup;
+ info.message = msg;
+ context->trace_callback(context, &info, context->trace_callback_data);
+cleanup:
+ free(str);
+ free(msg);
+ va_end(ap);
+}
+
+krb5_error_code KRB5_CALLCONV
+krb5_set_trace_callback(krb5_context context, krb5_trace_callback fn,
+ void *cb_data)
+{
+ /* Allow the old callback to destroy its data if necessary. */
+ if (context->trace_callback != NULL)
+ context->trace_callback(context, NULL, context->trace_callback_data);
+ context->trace_callback = fn;
+ context->trace_callback_data = cb_data;
+ return 0;
+}
+
+static void
+file_trace_cb(krb5_context context, const struct krb5_trace_info *info, void *data)
+{
+ int *fd = data;
+
+ if (info == NULL) {
+ /* Null info means destroy the callback data. */
+ free(fd);
+ return;
+ }
+
+ (void) write(*fd, info->message, strlen(info->message));
+}
+
+krb5_error_code KRB5_CALLCONV
+krb5_set_trace_filename(krb5_context context, const char *filename)
+{
+ int *fd;
+
+ /* Create callback data containing a file descriptor. */
+ fd = malloc(sizeof(*fd));
+ if (fd == NULL)
+ return ENOMEM;
+ *fd = open(filename, O_WRONLY|O_CREAT|O_APPEND, 0600);
+ if (*fd == -1) {
+ free(fd);
+ return errno;
+ }
+
+ return krb5_set_trace_callback(context, file_trace_cb, fd);
+}
+
+#else /* DISABLE_TRACING */
+
+krb5_error_code KRB5_CALLCONV
+krb5_set_trace_callback(krb5_context context, krb5_trace_callback fn,
+ void *cb_data)
+{
+ if (fn == NULL)
+ return 0;
+ return KRB5_TRACE_NOSUPP;
+}
+
+krb5_error_code KRB5_CALLCONV
+krb5_set_trace_filename(krb5_context context, const char *filename)
+{
+ return KRB5_TRACE_NOSUPP;
+}
+
+#endif /* DISABLE_TRACING */
More information about the cvs-krb5
mailing list