src/include/k5-trace.h

   1 /* -*- mode: c; c-basic-offset: 4; indent-tabs-mode: nil -*- */
   2 /*
   3  * include/k5-trace.h
   4  *
   5  * Copyright (C) 2010 by the Massachusetts Institute of Technology.
   6  * All rights reserved.
   7  *
   8  * Export of this software from the United States of America may
   9  *   require a specific license from the United States Government.
  10  *   It is the responsibility of any person or organization contemplating
  11  *   export to obtain such a license before exporting.
  12  *
  13  * WITHIN THAT CONSTRAINT, permission to use, copy, modify, and
  14  * distribute this software and its documentation for any purpose and
  15  * without fee is hereby granted, provided that the above copyright
  16  * notice appear in all copies and that both that copyright notice and
  17  * this permission notice appear in supporting documentation, and that
  18  * the name of M.I.T. not be used in advertising or publicity pertaining
  19  * to distribution of the software without specific, written prior
  20  * permission.  Furthermore if you modify this software you must label
  21  * your software as modified software and not distribute it in such a
  22  * fashion that it might be confused with the original M.I.T. software.
  23  * M.I.T. makes no representations about the suitability of
  24  * this software for any purpose.  It is provided "as is" without express
  25  * or implied warranty.
  26  *
  27  *
  28  * This header contains trace macro definitions, which map trace points within
  29  * the code to krb5int_trace() calls with descriptive text strings.
  30  *
  31  * Trace logging is intended to aid power users in diagnosing configuration
  32  * problems by showing what's going on behind the scenes of complex operations.
  33  * Although trace logging is sometimes useful to developers, it is not intended
  34  * as a replacement for a debugger, and it is not desirable to drown the user
  35  * in output.  Observe the following guidelines when adding trace points:
  36  *
  37  *   - Avoid mentioning function or variable names in messages.
  38  *
  39  *   - Try to convey what decisions are being made and what external inputs
  40  *     they are based on, not the process of making decisions.
  41  *
  42  *   - It is generally not necessary to trace before returning an unrecoverable
  43  *     error.  If an error code is unclear by itself, make it clearer with
  44  *     krb5_set_error_message().
  45  *
  46  *   - Keep macros simple.  Add format specifiers to krb5int_trace's formatter
  47  *     as necessary (and document them here) instead of transforming macro
  48  *     arguments.
  49  *
  50  *   - Like printf, the trace formatter interface is not type-safe.  Check your
  51  *     formats carefully.  Cast integral arguments to the appropriate type if
  52  *     they do not already patch.
  53  *
  54  * The following specifiers are supported by the formatter (see the
  55  * implementation in lib/krb5/os/trace.c for details):
  56  *
  57  *   {int}         int, in decimal
  58  *   {long}        long, in decimal
  59  *   {str}         const char *, display as C string
  60  *   {lenstr}      size_t and const char *, as a counted string
  61  *   {hexlenstr}   size_t and const char *, as hex bytes
  62  *   {hashlenstr}  size_t and const char *, as four-character hex hash
  63  *   {addrinfo}    struct addrinfo *, show socket type, address, port
  64  *   {data}        krb5_data *, display as counted string
  65  *   {hexdata}     krb5_data *, display as hex bytes
  66  *   {errno}       int, display as number/errorstring
  67  *   {kerr}        krb5_error_code, display as number/errorstring
  68  *   {keyblock}    const krb5_keyblock *, display enctype and hash of key
  69  *   {key}         krb5_key, display enctype and hash of key
  70  *   {cksum}       const krb5_checksum *, display cksumtype and hex checksum
  71  *   {princ}       krb5_principal, unparse and display
  72  *   {patypes}     krb5_pa_data **, display list of padata type numbers
  73  *   {etype}       krb5_enctype, display shortest name of enctype
  74  *   {etypes}      krb5_enctype *, display list of enctypes
  75  *   {ccache}      krb5_ccache, display type:name
  76  *   {creds}       krb5_creds *, display clientprinc -> serverprinc
  77  */
  78
  79 #ifndef K5_TRACE_H
  80 #define K5_TRACE_H
  81
  82 #if defined(DISABLE_TRACING)
  83 #define TRACE(ctx, args)
  84 #elif defined(_KRB5_INT_H)
  85 #define TRACE(ctx, args) \
  86     do { if (ctx->trace_callback != NULL) krb5int_trace args; } while (0)
  87 #else
  88 /* This source file isn't using k5-int.h and doesn't know the internals of the
  89  * context structure, so don't try to optimize away the call. */
  90 #define TRACE(ctx, args) krb5int_trace args
  91 #endif
  92
  93 #define TRACE_CC_DESTROY(c, cache) \
  94     TRACE(c, (c, "Destroying ccache {ccache}", cache))
  95 #define TRACE_CC_GEN_NEW(c, cache) \
  96     TRACE(c, (c, "Generating new unique ccache based on {ccache}", cache))
  97 #define TRACE_CC_GET_CONFIG(c, cache, princ, key, data) \
  98     TRACE(c, (c, "Read config in {ccache} for {princ}: {str}: {data}", \
  99               cache, princ, key, data))
 100 #define TRACE_CC_INIT(c, cache, princ) \
 101     TRACE(c, (c, "Initializing {ccache} with default princ {princ}", \
 102               cache, princ))
 103 #define TRACE_CC_MOVE(c, src, dst) \
 104     TRACE(c, (c, "Moving contents of ccache {src} to {dst}", src, dst))
 105 #define TRACE_CC_NEW_UNIQUE(c, type) \
 106     TRACE(c, (c, "Resolving unique ccache of type {str}", type))
 107 #define TRACE_CC_REMOVE(c, cache, creds) \
 108     TRACE(c, (c, "Removing {creds} from {ccache}", creds, cache))
 109 #define TRACE_CC_RETRIEVE(c, cache, creds, ret) \
 110     TRACE(c, (c, "Retrieving {creds} from {ccache} with result: {kerr}", \
 111               creds, cache, ret))
 112 #define TRACE_CC_RETRIEVE_REF(c, cache, creds, ret) \
 113     TRACE(c, (c, "Retrying {creds} with result: {kerr}", creds, ret))
 114 #define TRACE_CC_SET_CONFIG(c, cache, princ, key, data) \
 115     TRACE(c, (c, "Storing config in {ccache} for {princ}: {str}: {data}", \
 116               cache, princ, key, data))
 117 #define TRACE_CC_STORE(c, cache, creds) \
 118     TRACE(c, (c, "Storing {creds} in {ccache}", creds, cache))
 119 #define TRACE_CC_STORE_TKT(c, cache, creds) \
 120     TRACE(c, (c, "Also storing {creds} based on ticket", creds))
 121
 122 #define TRACE_FAST_ARMOR_CCACHE(c, ccache_name) \
 123     TRACE(c, (c, "FAST armor ccache: {str}", ccache_name))
 124 #define TRACE_FAST_ARMOR_CCACHE_KEY(c, keyblock) \
 125     TRACE(c, (c, "Armor ccache sesion key: {keyblock}", keyblock))
 126 #define TRACE_FAST_ARMOR_KEY(c, keyblock) \
 127     TRACE(c, (c, "FAST armor key: {keyblock}", keyblock))
 128 #define TRACE_FAST_CCACHE_CONFIG(c) \
 129     TRACE(c, (c, "Using FAST due to armor ccache negotiation result"))
 130 #define TRACE_FAST_DECODE(c) \
 131     TRACE(c, (c, "Decoding FAST response"))
 132 #define TRACE_FAST_ENCODE(c) \
 133     TRACE(c, (c, "Encoding request body and padata into FAST request"))
 134 #define TRACE_FAST_NEGO(c, avail) \
 135     TRACE(c, (c, "FAST negotiation: {str}available", (avail) ? "" : "un"))
 136 #define TRACE_FAST_PADATA_UPGRADE(c) \
 137     TRACE(c, (c, "Upgrading to FAST due to presence of PA_FX_FAST in reply"))
 138 #define TRACE_FAST_REPLY_KEY(c, keyblock) \
 139     TRACE(c, (c, "FAST reply key: {keyblock}", keyblock))
 140 #define TRACE_FAST_REQUIRED(c) \
 141     TRACE(c, (c, "Using FAST due to KRB5_FAST_REQUIRED flag"))
 142
 143 #define TRACE_GIC_PWD_CHANGED(c) \
 144     TRACE(c, (c, "Getting initial TGT with changed password"))
 145 #define TRACE_GIC_PWD_CHANGEPW(c, tries) \
 146     TRACE(c, (c, "Attempting password change; {int} tries remaining", tries))
 147 #define TRACE_GIC_PWD_EXPIRED(c) \
 148     TRACE(c, (c, "Principal expired; getting changepw ticket"))
 149 #define TRACE_GIC_PWD_MASTER(c) \
 150     TRACE(c, (c, "Retrying AS request with master KDC"))
 151
 152 #define TRACE_INIT_CREDS(c, princ) \
 153     TRACE(c, (c, "Getting initial credentials for {princ}", princ))
 154 #define TRACE_INIT_CREDS_AS_KEY_GAK(c, keyblock) \
 155     TRACE(c, (c, "AS key obtained from gak_fct: {keyblock}", keyblock))
 156 #define TRACE_INIT_CREDS_AS_KEY_PREAUTH(c, keyblock) \
 157     TRACE(c, (c, "AS key determined by preauth: {keyblock}", keyblock))
 158 #define TRACE_INIT_CREDS_DECRYPTED_REPLY(c, keyblock) \
 159     TRACE(c, (c, "Decrypted AS reply; session key is: {keyblock}", keyblock))
 160 #define TRACE_INIT_CREDS_ERROR_REPLY(c, code) \
 161     TRACE(c, (c, "Received error from KDC: {kerr}", code))
 162 #define TRACE_INIT_CREDS_GAK(c, salt, s2kparams) \
 163     TRACE(c, (c, "Getting AS key, salt \"{data}\", params \"{data}\"", \
 164               salt, s2kparams))
 165 #define TRACE_INIT_CREDS_PREAUTH_DECRYPT_FAIL(c, code) \
 166     TRACE(c, (c, "Decrypt with preauth AS key failed: {kerr}", code))
 167 #define TRACE_INIT_CREDS_RESTART_FAST(c) \
 168     TRACE(c, (c, "Restarting to upgrade to FAST"))
 169 #define TRACE_INIT_CREDS_RESTART_PREAUTH_FAILED(c) \
 170     TRACE(c, (c, "Restarting due to PREAUTH_FAILED from FAST negotiation"))
 171 #define TRACE_INIT_CREDS_REFERRAL(c, realm) \
 172     TRACE(c, (c, "Following referral to realm {data}", realm))
 173 #define TRACE_INIT_CREDS_RETRY_TCP(c) \
 174     TRACE(c, (c, "Request or response is too big for UDP; retrying with TCP"))
 175 #define TRACE_INIT_CREDS_SALT_PRINC(c, salt) \
 176     TRACE(c, (c, "Salt derived from principal: {data}", salt))
 177 #define TRACE_INIT_CREDS_SERVICE(c, service) \
 178     TRACE(c, (c, "Setting initial creds service to {string}", service))
 179
 180 #define TRACE_KT_GET_ENTRY(c, keytab, princ, vno, enctype, err) \
 181     TRACE(c, (c, "Retrieving {princ} from {keytab} (vno {int}, " \
 182               "enctype {etype}) with result: {kerr}", princ, keytab, \
 183               (int) vno, enctype, err))
 184
 185 #define TRACE_MK_REP(c, ctime, cusec, subkey, seqnum) \
 186     TRACE(c, (c, "Creating AP-REP, time {long}.{int}, subkey {keyblock}, " \
 187               "seqnum {int}", (long) ctime, (int) cusec, subkey, (int) seqnum))
 188
 189 #define TRACE_MK_REQ(c, creds, seqnum, subkey, sesskeyblock) \
 190     TRACE(c, (c, "Creating authenticator for {creds}, seqnum {int}, " \
 191               "subkey {key}, session key {keyblock}", creds, (int) seqnum, \
 192               subkey, sesskeyblock))
 193 #define TRACE_MK_REQ_ETYPES(c, etypes) \
 194     TRACE(c, (c, "Negotiating for enctypes in authenticator: {etypes}", \
 195               etypes))
 196
 197 #define TRACE_MSPAC_NOSRVCKSUM(c) \
 198     TRACE(c, (c, "MS PAC lacks a server checksum.  "\
 199               "Apple Open Directory bug?"))
 200 #define TRACE_MSPAC_DISCARD_UNVERF(c) \
 201     TRACE(c, (c, "Filtering out unverified MS PAC"))
 202
 203 #define TRACE_PREAUTH_COOKIE(c, len, data) \
 204     TRACE(c, (c, "Received cookie: {lenstr}", (size_t) len, data))
 205 #define TRACE_PREAUTH_ENC_TS_KEY_GAK(c, keyblock) \
 206     TRACE(c, (c, "AS key obtained for encrypted timestamp: {keyblock}", \
 207               keyblock))
 208 #define TRACE_PREAUTH_ENC_TS(c, sec, usec, plain, enc) \
 209     TRACE(c, (c, "Encrypted timestamp (for {long}.{int}): plain {hexdata}, " \
 210               "encrypted {hexdata}", (long) sec, (int) usec, plain, enc))
 211 #define TRACE_PREAUTH_ETYPE_INFO(c, etype, salt, s2kparams) \
 212     TRACE(c, (c, "Selected etype info: etype {etype}, salt \"{data}\", " \
 213               "params \"{data}\"", etype, salt, s2kparams))
 214 #define TRACE_PREAUTH_INFO_FAIL(c, patype, code) \
 215     TRACE(c, (c, "Preauth builtin info function failure, type={int}: {kerr}", \
 216               (int) patype, code))
 217 #define TRACE_PREAUTH_INPUT(c, padata) \
 218     TRACE(c, (c, "Processing preauth types: {patypes}", padata))
 219 #define TRACE_PREAUTH_OUTPUT(c, padata) \
 220     TRACE(c, (c, "Produced preauth for next request: {patypes}", padata))
 221 #define TRACE_PREAUTH_PROCESS(c, name, patype, flags, code) \
 222     TRACE(c, (c, "Preauth module {str} ({int}) (flags={int}) returned: " \
 223               "{kerr}", name, (int) patype, flags, code))
 224 #define TRACE_PREAUTH_SAM_KEY_GAK(c, keyblock) \
 225     TRACE(c, (c, "AS key obtained for SAM: {keyblock}", keyblock))
 226 #define TRACE_PREAUTH_SALT(c, salt, patype) \
 227     TRACE(c, (c, "Received salt \"{str}\" via padata type {int}", salt, \
 228               (int) patype))
 229 #define TRACE_PREAUTH_SKIP(c, name, patype) \
 230     TRACE(c, (c, "Skipping previously used preauth module {str} ({int})", \
 231               name, (int) patype))
 232 #define TRACE_PREAUTH_TRYAGAIN_INPUT(c, padata) \
 233     TRACE(c, (c, "Preauth tryagain input types: {patypes}", padata))
 234 #define TRACE_PREAUTH_TRYAGAIN_OUTPUT(c, padata) \
 235     TRACE(c, (c, "Followup preauth for next request: {patypes}", padata))
 236
 237 #define TRACE_RD_REP(c, ctime, cusec, subkey, seqnum) \
 238     TRACE(c, (c, "Read AP-REP, time {long}.{int}, subkey {keyblock}, " \
 239               "seqnum {int}", (long) ctime, (int) cusec, subkey, (int) seqnum))
 240 #define TRACE_RD_REP_DCE(c, ctime, cusec, seqnum) \
 241     TRACE(c, (c, "Read DCE-style AP-REP, time {long}.{int}, seqnum {int}", \
 242               (long) ctime, (int) cusec, (int) seqnum))
 243
 244 #define TRACE_RD_REQ_DECRYPT_ANY(c, princ, keyblock)                \
 245     TRACE(c, (c, "Decrypted AP-REQ with server principal {princ}: " \
 246               "{keyblock}", princ, keyblock))
 247 #define TRACE_RD_REQ_DECRYPT_SPECIFIC(c, princ, keyblock) \
 248     TRACE(c, (c, "Decrypted AP-REQ with specified server principal {princ}: " \
 249               "{keyblock}", princ, keyblock))
 250 #define TRACE_RD_REQ_NEGOTIATED_ETYPE(c, etype) \
 251     TRACE(c, (c, "Negotiated enctype based on authenticator: {etype}", \
 252               etype))
 253 #define TRACE_RD_REQ_SUBKEY(c, keyblock) \
 254     TRACE(c, (c, "Authenticator contains subkey: {keyblock}", keyblock))
 255 #define TRACE_RD_REQ_TICKET(c, client, server, keyblock) \
 256     TRACE(c, (c, "AP-REQ ticket: {princ} -> {princ}, session key {keyblock}", \
 257               client, server, keyblock))
 258
 259 #define TRACE_SENDTO_KDC(c, len, rlm, master, tcp) \
 260     TRACE(c, (c, "Sending request ({int} bytes) to {data}{str}{str}", len, \
 261               rlm, (master) ? " (master)" : "", (tcp) ? " (tcp only)" : ""))
 262 #define TRACE_SENDTO_KDC_MASTER(c, master) \
 263     TRACE(c, (c, "Response was{str} from master KDC", (master) ? "" : " not"))
 264 #define TRACE_SENDTO_KDC_RESPONSE(c, addr) \
 265     TRACE(c, (c, "Received answer from {addrinfo}", addr))
 266 #define TRACE_SENDTO_KDC_TCP_CONNECT(c, addr) \
 267     TRACE(c, (c, "Initiating TCP connection to {addrinfo}", addr))
 268 #define TRACE_SENDTO_KDC_TCP_DISCONNECT(c, addr) \
 269     TRACE(c, (c, "Terminating TCP connection to {addrinfo}", addr))
 270 #define TRACE_SENDTO_KDC_TCP_ERROR_CONNECT(c, addr, err) \
 271     TRACE(c, (c, "TCP error connecting to {addrinfo}: {errno}", addr, err))
 272 #define TRACE_SENDTO_KDC_TCP_ERROR_RECV(c, addr, err) \
 273     TRACE(c, (c, "TCP error receiving from {addrinfo}: {errno}", addr, err))
 274 #define TRACE_SENDTO_KDC_TCP_ERROR_RECV_LEN(c, addr, err) \
 275     TRACE(c, (c, "TCP error receiving from {addrinfo}: {errno}", addr, err))
 276 #define TRACE_SENDTO_KDC_TCP_ERROR_SEND(c, addr, err) \
 277     TRACE(c, (c, "TCP error sending to {addrinfo}: {errno}", addr, err))
 278 #define TRACE_SENDTO_KDC_TCP_SEND(c, addr) \
 279     TRACE(c, (c, "Sending TCP request to {addrinfo}", addr))
 280 #define TRACE_SENDTO_KDC_UDP_ERROR_RECV(c, addr, err) \
 281     TRACE(c, (c, "UDP error receiving from {addrinfo}: {errno}", addr, err))
 282 #define TRACE_SENDTO_KDC_UDP_ERROR_SEND_INITIAL(c, addr, err) \
 283     TRACE(c, (c, "UDP error sending to {addrinfo}: {errno}", addr, err))
 284 #define TRACE_SENDTO_KDC_UDP_ERROR_SEND_RETRY(c, addr, err) \
 285     TRACE(c, (c, "UDP error sending to {addrinfo}: {errno}", addr, err))
 286 #define TRACE_SENDTO_KDC_UDP_SEND_INITIAL(c, addr) \
 287     TRACE(c, (c, "Sending initial UDP request to {addrinfo}", addr))
 288 #define TRACE_SENDTO_KDC_UDP_SEND_RETRY(c, addr) \
 289     TRACE(c, (c, "Sending retry UDP request to {addrinfo}", addr))
 290
 291 #define TRACE_SEND_TGS_ETYPES(c, etypes) \
 292     TRACE(c, (c, "etypes requested in TGS request: {etypes}", etypes))
 293 #define TRACE_SEND_TGS_SUBKEY(c, keyblock) \
 294     TRACE(c, (c, "Generated subkey for TGS request: {keyblock}", keyblock))
 295
 296 #define TRACE_TGS_REPLY(c, client, server, keyblock) \
 297     TRACE(c, (c, "TGS reply is for {princ} -> {princ} with session key " \
 298               "{keyblock}", client, server, keyblock))
 299 #define TRACE_TGS_REPLY_DECODE_SESSION(c, keyblock) \
 300     TRACE(c, (c, "TGS reply didn't decode with subkey; trying session key " \
 301               "({keyblock)}", keyblock))
 302
 303 #define TRACE_TKT_CREDS(c, creds, cache) \
 304     TRACE(c, (c, "Getting credentials {creds} using ccache {ccache}", \
 305               creds, cache))
 306 #define TRACE_TKT_CREDS_ADVANCE(c, realm) \
 307     TRACE(c, (c, "Received TGT for {data}; advancing current realm", realm))
 308 #define TRACE_TKT_CREDS_CACHED_INTERMEDIATE_TGT(c, tgt) \
 309     TRACE(c, (c, "Found cached TGT for intermediate realm: {creds}", tgt))
 310 #define TRACE_TKT_CREDS_CACHED_SERVICE_TGT(c, tgt) \
 311     TRACE(c, (c, "Found cached TGT for service realm: {creds}", tgt))
 312 #define TRACE_TKT_CREDS_CLOSER_REALM(c, realm) \
 313     TRACE(c, (c, "Trying next closer realm in path: {data}", realm))
 314 #define TRACE_TKT_CREDS_COMPLETE(c, princ) \
 315     TRACE(c, (c, "Received creds for desired service {princ}", princ))
 316 #define TRACE_TKT_CREDS_FALLBACK(c, realm) \
 317     TRACE(c, (c, "Local realm referral failed; trying fallback realm {data}", \
 318               realm))
 319 #define TRACE_TKT_CREDS_LOCAL_TGT(c, tgt) \
 320     TRACE(c, (c, "Starting with TGT for client realm: {creds}", tgt))
 321 #define TRACE_TKT_CREDS_NON_TGT(c, princ) \
 322     TRACE(c, (c, "Received non-TGT referral response ({princ}); trying " \
 323               "again without referrals", princ))
 324 #define TRACE_TKT_CREDS_OFFPATH(c, realm) \
 325     TRACE(c, (c, "Received TGT for offpath realm {data}", realm))
 326 #define TRACE_TKT_CREDS_REFERRAL(c, princ) \
 327     TRACE(c, (c, "Following referral TGT {princ}", princ))
 328 #define TRACE_TKT_CREDS_REFERRAL_REALM(c, princ) \
 329     TRACE(c, (c, "Server has referral realm; starting with {princ}", princ))
 330 #define TRACE_TKT_CREDS_RESPONSE_CODE(c, code) \
 331     TRACE(c, (c, "TGS request result: {kerr}", code))
 332 #define TRACE_TKT_CREDS_RETRY_TCP(c) \
 333     TRACE(c, (c, "Request or response is too big for UDP; retrying with TCP"))
 334 #define TRACE_TKT_CREDS_SERVICE_REQ(c, princ, referral) \
 335     TRACE(c, (c, "Requesting tickets for {princ}, referrals {str}", princ, \
 336               (referral) ? "on" : "off"))
 337 #define TRACE_TKT_CREDS_TARGET_TGT(c, princ) \
 338     TRACE(c, (c, "Received TGT for service realm: {princ}", princ))
 339 #define TRACE_TKT_CREDS_TARGET_TGT_OFFPATH(c, princ) \
 340     TRACE(c, (c, "Received TGT for service realm: {princ}", princ))
 341 #define TRACE_TKT_CREDS_TGT_REQ(c, next, cur) \
 342     TRACE(c, (c, "Requesting TGT {princ} using TGT {princ}", next, cur))
 343 #define TRACE_TKT_CREDS_WRONG_ENCTYPE(c) \
 344     TRACE(c, (c, "Retrying TGS request with desired service ticket enctypes"))
 345
 346 #endif /* K5_TRACE_H */