Trace logging
authorGreg Hudson <ghudson@mit.edu>
Mon, 7 Jun 2010 18:26:17 +0000 (18:26 +0000)
committerGreg Hudson <ghudson@mit.edu>
Mon, 7 Jun 2010 18:26:17 +0000 (18:26 +0000)
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

ticket: 6737

git-svn-id: svn://anonsvn.mit.edu/krb5/trunk@24118 dc483132-0cff-0310-8789-dd5450dbe970

24 files changed:
src/include/cm.h
src/include/k5-int.h
src/include/k5-trace.h [new file with mode: 0644]
src/include/krb5/krb5.hin
src/lib/krb5/ccache/ccbase.c
src/lib/krb5/ccache/ccfns.c
src/lib/krb5/error_tables/krb5_err.et
src/lib/krb5/keytab/ktfns.c
src/lib/krb5/krb/fast.c
src/lib/krb5/krb/gc_via_tkt.c
src/lib/krb5/krb/get_creds.c
src/lib/krb5/krb/get_in_tkt.c
src/lib/krb5/krb/gic_pwd.c
src/lib/krb5/krb/init_ctx.c
src/lib/krb5/krb/mk_rep.c
src/lib/krb5/krb/mk_req_ext.c
src/lib/krb5/krb/preauth2.c
src/lib/krb5/krb/rd_rep.c
src/lib/krb5/krb/rd_req_dec.c
src/lib/krb5/krb/send_tgs.c
src/lib/krb5/libkrb5.exports
src/lib/krb5/os/Makefile.in
src/lib/krb5/os/sendto_kdc.c
src/lib/krb5/os/trace.c [new file with mode: 0644]

index 240735a3b1351962f67fc8b952a27fbff7e430ce..cf5ff222bcf020472fd9ff514373ab52bae00e90 100644 (file)
@@ -60,7 +60,8 @@ struct conn_state {
     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 {
index 184549ce0a526bb6d3c2c7db28820096c65cbcb1..19bf26b380b21660b12b76b420213167c29adbb5 100644 (file)
 #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 @@ typedef unsigned char   u_char;
 
 
 #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 _krb5_context {
     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_error_code krb5int_parse_enctype_list(krb5_context context, char *profstr,
     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 */
diff --git a/src/include/k5-trace.h b/src/include/k5-trace.h
new file mode 100644 (file)
index 0000000..1a2d78e
--- /dev/null
@@ -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 */
index 22a2a24e8c91a690221e5c80563f265031ce8ca4..7d7e425a3e2e4f7409c3f6b861d6413cf3ad4da0 100644 (file)
@@ -2668,6 +2668,40 @@ krb5_pac_verify(krb5_context context, const krb5_pac pac,
 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
index 023c7b158f434595306ee423c679ab8e15e7643c..ab163b3d1bddfd7a4d84c37279e4e1badf830270 100644 (file)
@@ -295,6 +295,7 @@ krb5_cc_new_unique(
 
     *id = NULL;
 
+    TRACE_CC_NEW_UNIQUE(context, type);
     err = krb5int_cc_getops(context, type, &ops);
     if (err)
         return err;
@@ -373,6 +374,7 @@ krb5_cc_move(krb5_context context, krb5_ccache src, krb5_ccache dst)
     krb5_error_code ret = 0;
     krb5_principal princ = NULL;
 
+    TRACE_CC_MOVE(context, src, dst);
     ret = krb5_cccol_lock(context);
     if (ret) {
         return ret;
index 088fdf6e36ff92e1a7065e276f3e04b0b68dd7ef..01acd22f22f7bd1b20e30cbd1d3e438c2541baea 100644 (file)
@@ -40,6 +40,7 @@ krb5_cc_get_name (krb5_context context, krb5_ccache cache)
 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_error_code KRB5_CALLCONV
 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 @@ krb5_cc_store_cred (krb5_context context, krb5_ccache cache,
     /* 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 @@ krb5_cc_store_cred (krb5_context context, krb5_ccache cache,
     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_cc_retrieve_cred (krb5_context context, krb5_ccache cache,
     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 @@ krb5_cc_retrieve_cred (krb5_context context, krb5_ccache cache,
     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_error_code KRB5_CALLCONV
 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_cc_set_config (krb5_context context, krb5_ccache id,
     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 @@ krb5_cc_get_config (krb5_context context, krb5_ccache id,
     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);
index 56434ad4797ca85797e61f462f395ccf1fc747b5..b771122d786836196760782d89dd96878a7a105c 100644 (file)
@@ -351,4 +351,6 @@ error_code KRB5_ERR_FAST_REQUIRED, "FAST protected pre-authentication required b
 
 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
index 3496c096474183970bc913e3c84be1ac7c938d59..33c91844d146d769554a7f3b9ea4045ecc76b16e 100644 (file)
@@ -72,6 +72,7 @@ krb5_kt_get_entry(krb5_context context, krb5_keytab keytab,
     }
     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;
index 30be3818c998d80cf6db1b3661e3be96b3565233..50321cc86c987b5995884a51d6f3bbd1663dc94f 100644 (file)
@@ -69,10 +69,12 @@ fast_armor_ap_request(krb5_context context,
     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 @@ fast_armor_ap_request(krb5_context context,
                                       &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 @@ krb5int_fast_as_armor(krb5_context context,
     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 @@ krb5int_fast_as_armor(krb5_context context,
             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 @@ krb5int_fast_prep_req(krb5_context context,
     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 @@ decrypt_fast_reply(krb5_context context,
     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 @@ krb5int_fast_reply_key(krb5_context context,
                                       "strengthenkey", existing_key,
                                       "replykey", &key);
         if (retval == 0) {
+            TRACE_FAST_REPLY_KEY(context, key);
             *out_key = *key;
             free(key);
         }
@@ -621,6 +633,7 @@ krb5int_fast_verify_nego(krb5_context context,
             *fast_avail = (pa != NULL);
         }
     }
+    TRACE_FAST_NEGO(context, *fast_avail);
     if (checksum)
         krb5_free_checksum(context, checksum);
     return retval;
@@ -636,6 +649,7 @@ krb5int_upgrade_to_fast_p(krb5_context context,
     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;
     }
index 0ab421383f38ea66800651cda21573741e482aae..5bee608a737c02063d3ddd4c988754ffebeb4bd6 100644 (file)
@@ -55,6 +55,8 @@ kdcrep2creds(krb5_context context, krb5_kdc_rep *pkdcrep, krb5_address *const *a
                                               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 @@ krb5int_process_tgs_reply(krb5_context context,
                                     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)
index 0e4956e2620cd25301ebf3caa229cefdeb1e285b..eb96a2df2932a408854a92fbb0354668d7386359 100644 (file)
@@ -301,6 +301,8 @@ make_request_for_tgt(krb5_context context, krb5_tkt_creds_context ctx,
     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 @@ make_request_for_service(krb5_context context, krb5_tkt_creds_context ctx,
     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 @@ get_creds_from_tgs_reply(krb5_context context, krb5_tkt_creds_context ctx,
 
     /* 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 @@ complete(krb5_context context, krb5_tkt_creds_context ctx)
 {
     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 @@ try_fallback_realm(krb5_context context, krb5_tkt_creds_context ctx)
     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 @@ step_referrals(krb5_context context, krb5_tkt_creds_context ctx)
                                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 @@ step_referrals(krb5_context context, krb5_tkt_creds_context ctx)
     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 @@ step_get_tgt_offpath(krb5_context context, krb5_tkt_creds_context ctx)
 
     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 @@ get_tgt_request(krb5_context context, krb5_tkt_creds_context ctx)
             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 @@ step_get_tgt(krb5_context context, krb5_tkt_creds_context ctx)
              * 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 @@ step_get_tgt(krb5_context context, krb5_tkt_creds_context ctx)
                 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 @@ step_get_tgt(krb5_context context, krb5_tkt_creds_context ctx)
             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 @@ begin_get_tgt(krb5_context context, krb5_tkt_creds_context ctx)
     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 @@ begin_get_tgt(krb5_context context, krb5_tkt_creds_context ctx)
         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 @@ begin(krb5_context context, krb5_tkt_creds_context ctx)
         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_tkt_creds_init(krb5_context context, krb5_ccache ccache,
     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 @@ krb5_tkt_creds_get(krb5_context context, krb5_tkt_creds_context ctx)
         /* 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);
 
index 63402ca0329e18c433de0b5d3915fbfc0a27f28c..28a23f2c43705811023fa9c28d512b07a06ad13b 100644 (file)
@@ -557,9 +557,10 @@ init_creds_get(krb5_context context,
                                     &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 @@ krb5_init_creds_init(krb5_context context,
     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 @@ krb5_init_creds_set_service(krb5_context context,
 {
     char *s;
 
+    TRACE_INIT_CREDS_SERVICE(context, service);
+
     s = strdup(service);
     if (s == NULL)
         return ENOMEM;
@@ -1018,6 +1023,8 @@ init_creds_validate_reply(krb5_context context,
 
         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 @@ static krb5_boolean
 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 @@ init_creds_step_reply(krb5_context context,
                 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 @@ init_creds_step_reply(krb5_context context,
      */
     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 @@ init_creds_step_reply(krb5_context context,
        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 @@ init_creds_step_reply(krb5_context context,
                                &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 @@ init_creds_step_reply(krb5_context context,
             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);
index 7b437272f87f9d0e383d9a45c065c388502bdb76..6df9014986728eb8ddff575bf3268d40000b9a3d 100644 (file)
@@ -173,6 +173,7 @@ krb5_get_init_creds_password(krb5_context context,
        the master kdc */
 
     if (!use_master) {
+        TRACE_GIC_PWD_MASTER(context);
         use_master = 1;
 
         if (as_reply) {
@@ -220,6 +221,7 @@ krb5_get_init_creds_password(krb5_context context,
      */
     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 @@ krb5_get_init_creds_password(krb5_context context,
             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 @@ krb5_get_init_creds_password(krb5_context context,
        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,
index e72534cccbf3dc12c1ca0cd8ebd3cc66e5274132..e7419f5d4a7c822512765a445186099ca6456e1f 100644 (file)
@@ -234,8 +234,12 @@ init_common (krb5_context *context, krb5_boolean secure, krb5_boolean kdc)
     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_free_context(krb5_context ctx)
 
     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);
 }
index b50c057654d43c36c98b9861d6edb3601db03e61..af024042b65e91203ede99c46eb243b208f88ce1 100644 (file)
@@ -113,6 +113,9 @@ k5_mk_rep(krb5_context context, krb5_auth_context auth_context,
     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;
index 554dda360ad233e891ae42a2593c771bb9724e30..3a4004dc080bcb99bb2ffb9079f5c9c6b07c934b 100644 (file)
@@ -135,10 +135,11 @@ krb5_mk_req_extended(krb5_context context, krb5_auth_context *auth_context,
     /* 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 @@ krb5_mk_req_extended(krb5_context context, krb5_auth_context *auth_context,
             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 @@ generate_authenticator(krb5_context context, krb5_authenticator *authent,
 
     /* 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)
index ce8d10536e354b4da59426bd41296ee3206c808f..c07fc46da742567ce4141f19c343d7ae4df3ffcd 100644 (file)
@@ -540,10 +540,7 @@ run_preauth_plugins(krb5_context kcontext,
         /* 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 @@ run_preauth_plugins(krb5_context kcontext,
                                      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 @@ pa_salt(krb5_context context, krb5_kdc_req *request, krb5_pa_data *in_padata,
     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 @@ pa_fx_cookie(krb5_context context, krb5_kdc_req *request,
 {
     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 @@ pa_enc_timestamp(krb5_context context, krb5_kdc_req *request,
                                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 @@ pa_enc_timestamp(krb5_context context, krb5_kdc_req *request,
     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 @@ pa_sam(krb5_context context, krb5_kdc_req *request, krb5_pa_data *in_padata,
             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 @@ krb5_do_preauth_tryagain(krb5_context kcontext,
         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 @@ krb5_do_preauth_tryagain(krb5_context kcontext,
                     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 @@ krb5_do_preauth(krb5_context context,
         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 @@ krb5_do_preauth(krb5_context context,
                                                       &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 @@ krb5_do_preauth(krb5_context context,
                                                        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 @@ krb5_do_preauth(krb5_context context,
         }
     }
 
+    TRACE_PREAUTH_OUTPUT(context, out_pa_list);
     *out_padata = out_pa_list;
     if (etype_info)
         krb5_free_etype_info(context, etype_info);
index 45c9901875d364aee31597e084b2494911701e23..2fdb2a04ac23a72d089fcca6aed47f27eb0a3788 100644 (file)
@@ -133,6 +133,9 @@ krb5_rd_rep(krb5_context context, krb5_auth_context auth_context,
     /* 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 @@ krb5_rd_rep_dce(krb5_context context, krb5_auth_context auth_context,
         goto clean_scratch;
     }
 
+    TRACE_RD_REP_DCE(context, repl->ctime, repl->cusec, repl->seq_number);
+
 clean_scratch:
     memset(scratch.data, 0, scratch.length);
 
index 21728a5279bca815b8ba7334b0d6713ec4441a90..014002981b9f7ee8c69781e45b385dfff1cc9260 100644 (file)
@@ -97,6 +97,10 @@ rd_req_decrypt_tkt_part(krb5_context context, const krb5_ap_req *req,
                                    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 @@ rd_req_decrypt_tkt_part(krb5_context context, const krb5_ap_req *req,
             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 @@ rd_req_decoded_opt(krb5_context context, krb5_auth_context *auth_context,
                                               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 @@ rd_req_decoded_opt(krb5_context context, krb5_auth_context *auth_context,
                              &(*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))))
index 83cc2158d63c724194d1e21c4bcdf6def454c2a6..41ab4ec61f5b4dd8cbf87fdee3603820a21f9076 100644 (file)
@@ -211,6 +211,7 @@ krb5int_make_tgs_request_ext(krb5_context context,
     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 @@ krb5int_make_tgs_request_ext(krb5_context context,
         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)))
index 8ed5441af5c9bf62ddc4adf5e1be8f4d6fdc31a4..2bd597204b81c01e80f39f670507a5b827f41315 100644 (file)
@@ -587,9 +587,11 @@ krb5int_free_addrlist
 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
index 6a1ffd13fdd0edadbd0e76881ce24e8a7500d7ba..0852e144b6274a98c918c85d2317ab85156db28c 100644 (file)
@@ -50,6 +50,7 @@ STLIBOBJS= \
         thread_safe.o   \
        timeofday.o     \
        toffset.o       \
+       trace.o         \
        unlck_file.o    \
        ustime.o        \
        write_msg.o
@@ -93,6 +94,7 @@ OBJS= \
         $(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 @@ SRCS= \
         $(srcdir)/thread_safe.c \
        $(srcdir)/timeofday.c   \
        $(srcdir)/toffset.c     \
+       $(srcdir)/trace.c       \
        $(srcdir)/unlck_file.c  \
        $(srcdir)/ustime.c      \
        $(srcdir)/write_msg.c
index 341afe891cd72528e20b24252ff3affd1d4ac48a..4cdffe716a29be004687078bc4b3d58519dcc51f 100644 (file)
@@ -371,6 +371,7 @@ krb5_sendto_kdc (krb5_context context, const krb5_data *message,
 
     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 @@ krb5_sendto_kdc (krb5_context context, const krb5_data *message,
                         *use_master = 1;
                     krb5int_free_addrlist (&addrs3);
                 }
+                TRACE_SENDTO_KDC_MASTER(context, *use_master);
             }
             krb5int_free_addrlist (&addrs);
             return 0;
@@ -575,10 +577,10 @@ krb5int_cm_call_select (const struct select_state *in,
     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 @@ setup_connection (struct conn_state *state, struct addrinfo *ai,
 }
 
 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 @@ start_connection (struct conn_state *state,
             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 @@ start_connection (struct conn_state *state,
         }
     } 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 @@ start_connection (struct conn_state *state,
         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 @@ start_connection (struct conn_state *state,
    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 @@ maybe_send (struct conn_state *conn,
     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 @@ maybe_send (struct conn_state *conn,
         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 @@ get_so_error(int fd)
    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 @@ service_tcp_fd (struct conn_state *conn, struct select_state *selstate,
             /* 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 @@ service_tcp_fd (struct conn_state *conn, struct select_state *selstate,
          */
         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 @@ service_tcp_fd (struct conn_state *conn, struct select_state *selstate,
                ((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 @@ service_tcp_fd (struct conn_state *conn, struct select_state *selstate,
                 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 @@ service_tcp_fd (struct conn_state *conn, struct select_state *selstate,
                                 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 @@ service_tcp_fd (struct conn_state *conn, struct select_state *selstate,
 }
 
 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 @@ service_udp_fd(struct conn_state *conn, struct select_state *selstate,
 
     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 @@ service_fds (krb5_context context,
                    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 @@ krb5int_sendto (krb5_context context, const krb5_data *message,
             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 @@ krb5int_sendto (krb5_context context, const krb5_data *message,
         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);
diff --git a/src/lib/krb5/os/trace.c b/src/lib/krb5/os/trace.c
new file mode 100644 (file)
index 0000000..8db9c50
--- /dev/null
@@ -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 */