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_ENCTYPE_LIST_UNKNOWN(c, profvar, name) \
 153     TRACE(c, (c, "Unrecognized enctype name in {str}: {str}", profvar, name))
 154
 155 #define TRACE_INIT_CREDS(c, princ) \
 156     TRACE(c, (c, "Getting initial credentials for {princ}", princ))
 157 #define TRACE_INIT_CREDS_AS_KEY_GAK(c, keyblock) \
 158     TRACE(c, (c, "AS key obtained from gak_fct: {keyblock}", keyblock))
 159 #define TRACE_INIT_CREDS_AS_KEY_PREAUTH(c, keyblock) \
 160     TRACE(c, (c, "AS key determined by preauth: {keyblock}", keyblock))
 161 #define TRACE_INIT_CREDS_DECRYPTED_REPLY(c, keyblock) \
 162     TRACE(c, (c, "Decrypted AS reply; session key is: {keyblock}", keyblock))
 163 #define TRACE_INIT_CREDS_ERROR_REPLY(c, code) \
 164     TRACE(c, (c, "Received error from KDC: {kerr}", code))
 165 #define TRACE_INIT_CREDS_GAK(c, salt, s2kparams) \
 166     TRACE(c, (c, "Getting AS key, salt \"{data}\", params \"{data}\"", \
 167               salt, s2kparams))
 168 #define TRACE_INIT_CREDS_PREAUTH_DECRYPT_FAIL(c, code) \
 169     TRACE(c, (c, "Decrypt with preauth AS key failed: {kerr}", code))
 170 #define TRACE_INIT_CREDS_RESTART_FAST(c) \
 171     TRACE(c, (c, "Restarting to upgrade to FAST"))
 172 #define TRACE_INIT_CREDS_RESTART_PREAUTH_FAILED(c) \
 173     TRACE(c, (c, "Restarting due to PREAUTH_FAILED from FAST negotiation"))
 174 #define TRACE_INIT_CREDS_REFERRAL(c, realm) \
 175     TRACE(c, (c, "Following referral to realm {data}", realm))
 176 #define TRACE_INIT_CREDS_RETRY_TCP(c) \
 177     TRACE(c, (c, "Request or response is too big for UDP; retrying with TCP"))
 178 #define TRACE_INIT_CREDS_SALT_PRINC(c, salt) \
 179     TRACE(c, (c, "Salt derived from principal: {data}", salt))
 180 #define TRACE_INIT_CREDS_SERVICE(c, service) \
 181     TRACE(c, (c, "Setting initial creds service to {string}", service))
 182
 183 #define TRACE_KT_GET_ENTRY(c, keytab, princ, vno, enctype, err) \
 184     TRACE(c, (c, "Retrieving {princ} from {keytab} (vno {int}, " \
 185               "enctype {etype}) with result: {kerr}", princ, keytab, \
 186               (int) vno, enctype, err))
 187
 188 #define TRACE_MK_REP(c, ctime, cusec, subkey, seqnum) \
 189     TRACE(c, (c, "Creating AP-REP, time {long}.{int}, subkey {keyblock}, " \
 190               "seqnum {int}", (long) ctime, (int) cusec, subkey, (int) seqnum))
 191
 192 #define TRACE_MK_REQ(c, creds, seqnum, subkey, sesskeyblock) \
 193     TRACE(c, (c, "Creating authenticator for {creds}, seqnum {int}, " \
 194               "subkey {key}, session key {keyblock}", creds, (int) seqnum, \
 195               subkey, sesskeyblock))
 196 #define TRACE_MK_REQ_ETYPES(c, etypes) \
 197     TRACE(c, (c, "Negotiating for enctypes in authenticator: {etypes}", \
 198               etypes))
 199
 200 #define TRACE_MSPAC_NOSRVCKSUM(c) \
 201     TRACE(c, (c, "MS PAC lacks a server checksum.  "\
 202               "Apple Open Directory bug?"))
 203 #define TRACE_MSPAC_DISCARD_UNVERF(c) \
 204     TRACE(c, (c, "Filtering out unverified MS PAC"))
 205
 206 #define TRACE_PREAUTH_COOKIE(c, len, data) \
 207     TRACE(c, (c, "Received cookie: {lenstr}", (size_t) len, data))
 208 #define TRACE_PREAUTH_ENC_TS_KEY_GAK(c, keyblock) \
 209     TRACE(c, (c, "AS key obtained for encrypted timestamp: {keyblock}", \
 210               keyblock))
 211 #define TRACE_PREAUTH_ENC_TS(c, sec, usec, plain, enc) \
 212     TRACE(c, (c, "Encrypted timestamp (for {long}.{int}): plain {hexdata}, " \
 213               "encrypted {hexdata}", (long) sec, (int) usec, plain, enc))
 214 #define TRACE_PREAUTH_ETYPE_INFO(c, etype, salt, s2kparams) \
 215     TRACE(c, (c, "Selected etype info: etype {etype}, salt \"{data}\", " \
 216               "params \"{data}\"", etype, salt, s2kparams))
 217 #define TRACE_PREAUTH_INFO_FAIL(c, patype, code) \
 218     TRACE(c, (c, "Preauth builtin info function failure, type={int}: {kerr}", \
 219               (int) patype, code))
 220 #define TRACE_PREAUTH_INPUT(c, padata) \
 221     TRACE(c, (c, "Processing preauth types: {patypes}", padata))
 222 #define TRACE_PREAUTH_OUTPUT(c, padata) \
 223     TRACE(c, (c, "Produced preauth for next request: {patypes}", padata))
 224 #define TRACE_PREAUTH_PROCESS(c, name, patype, flags, code) \
 225     TRACE(c, (c, "Preauth module {str} ({int}) (flags={int}) returned: " \
 226               "{kerr}", name, (int) patype, flags, code))
 227 #define TRACE_PREAUTH_SAM_KEY_GAK(c, keyblock) \
 228     TRACE(c, (c, "AS key obtained for SAM: {keyblock}", keyblock))
 229 #define TRACE_PREAUTH_SALT(c, salt, patype) \
 230     TRACE(c, (c, "Received salt \"{str}\" via padata type {int}", salt, \
 231               (int) patype))
 232 #define TRACE_PREAUTH_SKIP(c, name, patype) \
 233     TRACE(c, (c, "Skipping previously used preauth module {str} ({int})", \
 234               name, (int) patype))
 235 #define TRACE_PREAUTH_TRYAGAIN_INPUT(c, padata) \
 236     TRACE(c, (c, "Preauth tryagain input types: {patypes}", padata))
 237 #define TRACE_PREAUTH_TRYAGAIN_OUTPUT(c, padata) \
 238     TRACE(c, (c, "Followup preauth for next request: {patypes}", padata))
 239
 240 #define TRACE_RD_REP(c, ctime, cusec, subkey, seqnum) \
 241     TRACE(c, (c, "Read AP-REP, time {long}.{int}, subkey {keyblock}, " \
 242               "seqnum {int}", (long) ctime, (int) cusec, subkey, (int) seqnum))
 243 #define TRACE_RD_REP_DCE(c, ctime, cusec, seqnum) \
 244     TRACE(c, (c, "Read DCE-style AP-REP, time {long}.{int}, seqnum {int}", \
 245               (long) ctime, (int) cusec, (int) seqnum))
 246
 247 #define TRACE_RD_REQ_DECRYPT_ANY(c, princ, keyblock)                \
 248     TRACE(c, (c, "Decrypted AP-REQ with server principal {princ}: " \
 249               "{keyblock}", princ, keyblock))
 250 #define TRACE_RD_REQ_DECRYPT_SPECIFIC(c, princ, keyblock) \
 251     TRACE(c, (c, "Decrypted AP-REQ with specified server principal {princ}: " \
 252               "{keyblock}", princ, keyblock))
 253 #define TRACE_RD_REQ_NEGOTIATED_ETYPE(c, etype) \
 254     TRACE(c, (c, "Negotiated enctype based on authenticator: {etype}", \
 255               etype))
 256 #define TRACE_RD_REQ_SUBKEY(c, keyblock) \
 257     TRACE(c, (c, "Authenticator contains subkey: {keyblock}", keyblock))
 258 #define TRACE_RD_REQ_TICKET(c, client, server, keyblock) \
 259     TRACE(c, (c, "AP-REQ ticket: {princ} -> {princ}, session key {keyblock}", \
 260               client, server, keyblock))
 261
 262 #define TRACE_SENDTO_KDC(c, len, rlm, master, tcp) \
 263     TRACE(c, (c, "Sending request ({int} bytes) to {data}{str}{str}", len, \
 264               rlm, (master) ? " (master)" : "", (tcp) ? " (tcp only)" : ""))
 265 #define TRACE_SENDTO_KDC_MASTER(c, master) \
 266     TRACE(c, (c, "Response was{str} from master KDC", (master) ? "" : " not"))
 267 #define TRACE_SENDTO_KDC_RESPONSE(c, addr) \
 268     TRACE(c, (c, "Received answer from {addrinfo}", addr))
 269 #define TRACE_SENDTO_KDC_TCP_CONNECT(c, addr) \
 270     TRACE(c, (c, "Initiating TCP connection to {addrinfo}", addr))
 271 #define TRACE_SENDTO_KDC_TCP_DISCONNECT(c, addr) \
 272     TRACE(c, (c, "Terminating TCP connection to {addrinfo}", addr))
 273 #define TRACE_SENDTO_KDC_TCP_ERROR_CONNECT(c, addr, err) \
 274     TRACE(c, (c, "TCP error connecting to {addrinfo}: {errno}", addr, err))
 275 #define TRACE_SENDTO_KDC_TCP_ERROR_RECV(c, addr, err) \
 276     TRACE(c, (c, "TCP error receiving from {addrinfo}: {errno}", addr, err))
 277 #define TRACE_SENDTO_KDC_TCP_ERROR_RECV_LEN(c, addr, err) \
 278     TRACE(c, (c, "TCP error receiving from {addrinfo}: {errno}", addr, err))
 279 #define TRACE_SENDTO_KDC_TCP_ERROR_SEND(c, addr, err) \
 280     TRACE(c, (c, "TCP error sending to {addrinfo}: {errno}", addr, err))
 281 #define TRACE_SENDTO_KDC_TCP_SEND(c, addr) \
 282     TRACE(c, (c, "Sending TCP request to {addrinfo}", addr))
 283 #define TRACE_SENDTO_KDC_UDP_ERROR_RECV(c, addr, err) \
 284     TRACE(c, (c, "UDP error receiving from {addrinfo}: {errno}", addr, err))
 285 #define TRACE_SENDTO_KDC_UDP_ERROR_SEND_INITIAL(c, addr, err) \
 286     TRACE(c, (c, "UDP error sending to {addrinfo}: {errno}", addr, err))
 287 #define TRACE_SENDTO_KDC_UDP_ERROR_SEND_RETRY(c, addr, err) \
 288     TRACE(c, (c, "UDP error sending to {addrinfo}: {errno}", addr, err))
 289 #define TRACE_SENDTO_KDC_UDP_SEND_INITIAL(c, addr) \
 290     TRACE(c, (c, "Sending initial UDP request to {addrinfo}", addr))
 291 #define TRACE_SENDTO_KDC_UDP_SEND_RETRY(c, addr) \
 292     TRACE(c, (c, "Sending retry UDP request to {addrinfo}", addr))
 293
 294 #define TRACE_SEND_TGS_ETYPES(c, etypes) \
 295     TRACE(c, (c, "etypes requested in TGS request: {etypes}", etypes))
 296 #define TRACE_SEND_TGS_SUBKEY(c, keyblock) \
 297     TRACE(c, (c, "Generated subkey for TGS request: {keyblock}", keyblock))
 298
 299 #define TRACE_TGS_REPLY(c, client, server, keyblock) \
 300     TRACE(c, (c, "TGS reply is for {princ} -> {princ} with session key " \
 301               "{keyblock}", client, server, keyblock))
 302 #define TRACE_TGS_REPLY_DECODE_SESSION(c, keyblock) \
 303     TRACE(c, (c, "TGS reply didn't decode with subkey; trying session key " \
 304               "({keyblock)}", keyblock))
 305
 306 #define TRACE_TKT_CREDS(c, creds, cache) \
 307     TRACE(c, (c, "Getting credentials {creds} using ccache {ccache}", \
 308               creds, cache))
 309 #define TRACE_TKT_CREDS_ADVANCE(c, realm) \
 310     TRACE(c, (c, "Received TGT for {data}; advancing current realm", realm))
 311 #define TRACE_TKT_CREDS_CACHED_INTERMEDIATE_TGT(c, tgt) \
 312     TRACE(c, (c, "Found cached TGT for intermediate realm: {creds}", tgt))
 313 #define TRACE_TKT_CREDS_CACHED_SERVICE_TGT(c, tgt) \
 314     TRACE(c, (c, "Found cached TGT for service realm: {creds}", tgt))
 315 #define TRACE_TKT_CREDS_CLOSER_REALM(c, realm) \
 316     TRACE(c, (c, "Trying next closer realm in path: {data}", realm))
 317 #define TRACE_TKT_CREDS_COMPLETE(c, princ) \
 318     TRACE(c, (c, "Received creds for desired service {princ}", princ))
 319 #define TRACE_TKT_CREDS_FALLBACK(c, realm) \
 320     TRACE(c, (c, "Local realm referral failed; trying fallback realm {data}", \
 321               realm))
 322 #define TRACE_TKT_CREDS_LOCAL_TGT(c, tgt) \
 323     TRACE(c, (c, "Starting with TGT for client realm: {creds}", tgt))
 324 #define TRACE_TKT_CREDS_NON_TGT(c, princ) \
 325     TRACE(c, (c, "Received non-TGT referral response ({princ}); trying " \
 326               "again without referrals", princ))
 327 #define TRACE_TKT_CREDS_OFFPATH(c, realm) \
 328     TRACE(c, (c, "Received TGT for offpath realm {data}", realm))
 329 #define TRACE_TKT_CREDS_REFERRAL(c, princ) \
 330     TRACE(c, (c, "Following referral TGT {princ}", princ))
 331 #define TRACE_TKT_CREDS_REFERRAL_REALM(c, princ) \
 332     TRACE(c, (c, "Server has referral realm; starting with {princ}", princ))
 333 #define TRACE_TKT_CREDS_RESPONSE_CODE(c, code) \
 334     TRACE(c, (c, "TGS request result: {kerr}", code))
 335 #define TRACE_TKT_CREDS_RETRY_TCP(c) \
 336     TRACE(c, (c, "Request or response is too big for UDP; retrying with TCP"))
 337 #define TRACE_TKT_CREDS_SERVICE_REQ(c, princ, referral) \
 338     TRACE(c, (c, "Requesting tickets for {princ}, referrals {str}", princ, \
 339               (referral) ? "on" : "off"))
 340 #define TRACE_TKT_CREDS_TARGET_TGT(c, princ) \
 341     TRACE(c, (c, "Received TGT for service realm: {princ}", princ))
 342 #define TRACE_TKT_CREDS_TARGET_TGT_OFFPATH(c, princ) \
 343     TRACE(c, (c, "Received TGT for service realm: {princ}", princ))
 344 #define TRACE_TKT_CREDS_TGT_REQ(c, next, cur) \
 345     TRACE(c, (c, "Requesting TGT {princ} using TGT {princ}", next, cur))
 346 #define TRACE_TKT_CREDS_WRONG_ENCTYPE(c) \
 347     TRACE(c, (c, "Retrying TGS request with desired service ticket enctypes"))
 348
 349 #endif /* K5_TRACE_H */