1 /* -*- mode: c; c-basic-offset: 4; indent-tabs-mode: nil -*- */
2 /* include/k5-trace.h */
4 * Copyright (C) 2010 by the Massachusetts Institute of Technology.
7 * Export of this software from the United States of America may
8 * require a specific license from the United States Government.
9 * It is the responsibility of any person or organization contemplating
10 * export to obtain such a license before exporting.
12 * WITHIN THAT CONSTRAINT, permission to use, copy, modify, and
13 * distribute this software and its documentation for any purpose and
14 * without fee is hereby granted, provided that the above copyright
15 * notice appear in all copies and that both that copyright notice and
16 * this permission notice appear in supporting documentation, and that
17 * the name of M.I.T. not be used in advertising or publicity pertaining
18 * to distribution of the software without specific, written prior
19 * permission. Furthermore if you modify this software you must label
20 * your software as modified software and not distribute it in such a
21 * fashion that it might be confused with the original M.I.T. software.
22 * M.I.T. makes no representations about the suitability of
23 * this software for any purpose. It is provided "as is" without express
24 * or implied warranty.
28 * This header contains trace macro definitions, which map trace points within
29 * the code to krb5int_trace() calls with descriptive text strings.
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:
37 * - Avoid mentioning function or variable names in messages.
39 * - Try to convey what decisions are being made and what external inputs
40 * they are based on, not the process of making decisions.
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().
46 * - Keep macros simple. Add format specifiers to krb5int_trace's formatter
47 * as necessary (and document them here) instead of transforming macro
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.
54 * The following specifiers are supported by the formatter (see the
55 * implementation in lib/krb5/os/trace.c for details):
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 * {connstate} struct conn_state *, 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
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)
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
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}", \
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}", \
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))
122 #define TRACE_CCSELECT_VTINIT_FAIL(c, ret) \
123 TRACE(c, (c, "ccselect module failed to init vtable: {kerr}", ret))
124 #define TRACE_CCSELECT_INIT_FAIL(c, name, ret) \
125 TRACE(c, (c, "ccselect module {str} failed to init: {kerr}", name, ret))
126 #define TRACE_CCSELECT_MODCHOICE(c, name, server, cache, princ) \
127 TRACE(c, (c, "ccselect module {str} chose cache {ccache} with client " \
128 "principal {princ} for server principal {princ}", name, cache, \
130 #define TRACE_CCSELECT_MODNOTFOUND(c, name, server, princ) \
131 TRACE(c, (c, "ccselect module {str} chose client principal {princ} " \
132 "for server principal {princ} but found no cache", name, princ, \
134 #define TRACE_CCSELECT_MODFAIL(c, name, ret, server) \
135 TRACE(c, (c, "ccselect module {str} yielded error {kerr} for server " \
136 "principal {princ}", name, ret, server))
137 #define TRACE_CCSELECT_NOTFOUND(c, server) \
138 TRACE(c, (c, "ccselect can't find appropriate cache for server " \
139 "principal {princ}", server))
140 #define TRACE_CCSELECT_DEFAULT(c, cache, server) \
141 TRACE(c, (c, "ccselect choosing default cache {ccache} for server " \
142 "principal {princ}", cache, server))
144 #define TRACE_FAST_ARMOR_CCACHE(c, ccache_name) \
145 TRACE(c, (c, "FAST armor ccache: {str}", ccache_name))
146 #define TRACE_FAST_ARMOR_CCACHE_KEY(c, keyblock) \
147 TRACE(c, (c, "Armor ccache sesion key: {keyblock}", keyblock))
148 #define TRACE_FAST_ARMOR_KEY(c, keyblock) \
149 TRACE(c, (c, "FAST armor key: {keyblock}", keyblock))
150 #define TRACE_FAST_CCACHE_CONFIG(c) \
151 TRACE(c, (c, "Using FAST due to armor ccache negotiation result"))
152 #define TRACE_FAST_DECODE(c) \
153 TRACE(c, (c, "Decoding FAST response"))
154 #define TRACE_FAST_ENCODE(c) \
155 TRACE(c, (c, "Encoding request body and padata into FAST request"))
156 #define TRACE_FAST_NEGO(c, avail) \
157 TRACE(c, (c, "FAST negotiation: {str}available", (avail) ? "" : "un"))
158 #define TRACE_FAST_PADATA_UPGRADE(c) \
159 TRACE(c, (c, "Upgrading to FAST due to presence of PA_FX_FAST in reply"))
160 #define TRACE_FAST_REPLY_KEY(c, keyblock) \
161 TRACE(c, (c, "FAST reply key: {keyblock}", keyblock))
162 #define TRACE_FAST_REQUIRED(c) \
163 TRACE(c, (c, "Using FAST due to KRB5_FAST_REQUIRED flag"))
165 #define TRACE_GIC_PWD_CHANGED(c) \
166 TRACE(c, (c, "Getting initial TGT with changed password"))
167 #define TRACE_GIC_PWD_CHANGEPW(c, tries) \
168 TRACE(c, (c, "Attempting password change; {int} tries remaining", tries))
169 #define TRACE_GIC_PWD_EXPIRED(c) \
170 TRACE(c, (c, "Principal expired; getting changepw ticket"))
171 #define TRACE_GIC_PWD_MASTER(c) \
172 TRACE(c, (c, "Retrying AS request with master KDC"))
174 #define TRACE_ENCTYPE_LIST_UNKNOWN(c, profvar, name) \
175 TRACE(c, (c, "Unrecognized enctype name in {str}: {str}", profvar, name))
177 #define TRACE_INIT_CREDS(c, princ) \
178 TRACE(c, (c, "Getting initial credentials for {princ}", princ))
179 #define TRACE_INIT_CREDS_AS_KEY_GAK(c, keyblock) \
180 TRACE(c, (c, "AS key obtained from gak_fct: {keyblock}", keyblock))
181 #define TRACE_INIT_CREDS_AS_KEY_PREAUTH(c, keyblock) \
182 TRACE(c, (c, "AS key determined by preauth: {keyblock}", keyblock))
183 #define TRACE_INIT_CREDS_DECRYPTED_REPLY(c, keyblock) \
184 TRACE(c, (c, "Decrypted AS reply; session key is: {keyblock}", keyblock))
185 #define TRACE_INIT_CREDS_ERROR_REPLY(c, code) \
186 TRACE(c, (c, "Received error from KDC: {kerr}", code))
187 #define TRACE_INIT_CREDS_GAK(c, salt, s2kparams) \
188 TRACE(c, (c, "Getting AS key, salt \"{data}\", params \"{data}\"", \
190 #define TRACE_INIT_CREDS_KEYTAB_LOOKUP(c, etypes) \
191 TRACE(c, (c, "Looked up etypes in keytab: {etypes}", etypes))
192 #define TRACE_INIT_CREDS_KEYTAB_LOOKUP_FAILED(c, code) \
193 TRACE(c, (c, "Couldn't lookup etypes in keytab: {kerr}", code))
194 #define TRACE_INIT_CREDS_PREAUTH_DECRYPT_FAIL(c, code) \
195 TRACE(c, (c, "Decrypt with preauth AS key failed: {kerr}", code))
196 #define TRACE_INIT_CREDS_RESTART_FAST(c) \
197 TRACE(c, (c, "Restarting to upgrade to FAST"))
198 #define TRACE_INIT_CREDS_RESTART_PREAUTH_FAILED(c) \
199 TRACE(c, (c, "Restarting due to PREAUTH_FAILED from FAST negotiation"))
200 #define TRACE_INIT_CREDS_REFERRAL(c, realm) \
201 TRACE(c, (c, "Following referral to realm {data}", realm))
202 #define TRACE_INIT_CREDS_RETRY_TCP(c) \
203 TRACE(c, (c, "Request or response is too big for UDP; retrying with TCP"))
204 #define TRACE_INIT_CREDS_SALT_PRINC(c, salt) \
205 TRACE(c, (c, "Salt derived from principal: {data}", salt))
206 #define TRACE_INIT_CREDS_SERVICE(c, service) \
207 TRACE(c, (c, "Setting initial creds service to {str}", service))
209 #define TRACE_KT_GET_ENTRY(c, keytab, princ, vno, enctype, err) \
210 TRACE(c, (c, "Retrieving {princ} from {keytab} (vno {int}, " \
211 "enctype {etype}) with result: {kerr}", princ, keytab, \
212 (int) vno, enctype, err))
214 #define TRACE_MK_REP(c, ctime, cusec, subkey, seqnum) \
215 TRACE(c, (c, "Creating AP-REP, time {long}.{int}, subkey {keyblock}, " \
216 "seqnum {int}", (long) ctime, (int) cusec, subkey, (int) seqnum))
218 #define TRACE_MK_REQ(c, creds, seqnum, subkey, sesskeyblock) \
219 TRACE(c, (c, "Creating authenticator for {creds}, seqnum {int}, " \
220 "subkey {key}, session key {keyblock}", creds, (int) seqnum, \
221 subkey, sesskeyblock))
222 #define TRACE_MK_REQ_ETYPES(c, etypes) \
223 TRACE(c, (c, "Negotiating for enctypes in authenticator: {etypes}", \
226 #define TRACE_MSPAC_VERIFY_FAIL(c, err) \
227 TRACE(c, (c, "PAC checksum verification failed: {kerr}", err))
228 #define TRACE_MSPAC_DISCARD_UNVERF(c) \
229 TRACE(c, (c, "Filtering out unverified MS PAC"))
231 #define TRACE_PREAUTH_COOKIE(c, len, data) \
232 TRACE(c, (c, "Received cookie: {lenstr}", (size_t) len, data))
233 #define TRACE_PREAUTH_ENC_TS_KEY_GAK(c, keyblock) \
234 TRACE(c, (c, "AS key obtained for encrypted timestamp: {keyblock}", \
236 #define TRACE_PREAUTH_ENC_TS(c, sec, usec, plain, enc) \
237 TRACE(c, (c, "Encrypted timestamp (for {long}.{int}): plain {hexdata}, " \
238 "encrypted {hexdata}", (long) sec, (int) usec, plain, enc))
239 #define TRACE_PREAUTH_ETYPE_INFO(c, etype, salt, s2kparams) \
240 TRACE(c, (c, "Selected etype info: etype {etype}, salt \"{data}\", " \
241 "params \"{data}\"", etype, salt, s2kparams))
242 #define TRACE_PREAUTH_INFO_FAIL(c, patype, code) \
243 TRACE(c, (c, "Preauth builtin info function failure, type={int}: {kerr}", \
245 #define TRACE_PREAUTH_INPUT(c, padata) \
246 TRACE(c, (c, "Processing preauth types: {patypes}", padata))
247 #define TRACE_PREAUTH_OUTPUT(c, padata) \
248 TRACE(c, (c, "Produced preauth for next request: {patypes}", padata))
249 #define TRACE_PREAUTH_PROCESS(c, name, patype, flags, code) \
250 TRACE(c, (c, "Preauth module {str} ({int}) (flags={int}) returned: " \
251 "{kerr}", name, (int) patype, flags, code))
252 #define TRACE_PREAUTH_SAM_KEY_GAK(c, keyblock) \
253 TRACE(c, (c, "AS key obtained for SAM: {keyblock}", keyblock))
254 #define TRACE_PREAUTH_SALT(c, salt, patype) \
255 TRACE(c, (c, "Received salt \"{str}\" via padata type {int}", salt, \
257 #define TRACE_PREAUTH_SKIP(c, name, patype) \
258 TRACE(c, (c, "Skipping previously used preauth module {str} ({int})", \
260 #define TRACE_PREAUTH_TRYAGAIN_INPUT(c, padata) \
261 TRACE(c, (c, "Preauth tryagain input types: {patypes}", padata))
262 #define TRACE_PREAUTH_TRYAGAIN_OUTPUT(c, padata) \
263 TRACE(c, (c, "Followup preauth for next request: {patypes}", padata))
265 #define TRACE_PROFILE_ERR(c,subsection, section, retval) \
266 TRACE(c, (c, "Bad value of {str} from [{str}] in conf file: {kerr}", \
267 subsection, section, retval))
269 #define TRACE_RD_REP(c, ctime, cusec, subkey, seqnum) \
270 TRACE(c, (c, "Read AP-REP, time {long}.{int}, subkey {keyblock}, " \
271 "seqnum {int}", (long) ctime, (int) cusec, subkey, (int) seqnum))
272 #define TRACE_RD_REP_DCE(c, ctime, cusec, seqnum) \
273 TRACE(c, (c, "Read DCE-style AP-REP, time {long}.{int}, seqnum {int}", \
274 (long) ctime, (int) cusec, (int) seqnum))
276 #define TRACE_RD_REQ_DECRYPT_ANY(c, princ, keyblock) \
277 TRACE(c, (c, "Decrypted AP-REQ with server principal {princ}: " \
278 "{keyblock}", princ, keyblock))
279 #define TRACE_RD_REQ_DECRYPT_SPECIFIC(c, princ, keyblock) \
280 TRACE(c, (c, "Decrypted AP-REQ with specified server principal {princ}: " \
281 "{keyblock}", princ, keyblock))
282 #define TRACE_RD_REQ_NEGOTIATED_ETYPE(c, etype) \
283 TRACE(c, (c, "Negotiated enctype based on authenticator: {etype}", \
285 #define TRACE_RD_REQ_SUBKEY(c, keyblock) \
286 TRACE(c, (c, "Authenticator contains subkey: {keyblock}", keyblock))
287 #define TRACE_RD_REQ_TICKET(c, client, server, keyblock) \
288 TRACE(c, (c, "AP-REQ ticket: {princ} -> {princ}, session key {keyblock}", \
289 client, server, keyblock))
291 #define TRACE_SENDTO_KDC(c, len, rlm, master, tcp) \
292 TRACE(c, (c, "Sending request ({int} bytes) to {data}{str}{str}", len, \
293 rlm, (master) ? " (master)" : "", (tcp) ? " (tcp only)" : ""))
294 #define TRACE_SENDTO_KDC_MASTER(c, master) \
295 TRACE(c, (c, "Response was{str} from master KDC", (master) ? "" : " not"))
296 #define TRACE_SENDTO_KDC_RESOLVING(c, hostname) \
297 TRACE(c, (c, "Resolving hostname {str}", hostname))
298 #define TRACE_SENDTO_KDC_RESPONSE(c, conn) \
299 TRACE(c, (c, "Received answer from {connstate}", conn))
300 #define TRACE_SENDTO_KDC_TCP_CONNECT(c, conn) \
301 TRACE(c, (c, "Initiating TCP connection to {connstate}", conn))
302 #define TRACE_SENDTO_KDC_TCP_DISCONNECT(c, conn) \
303 TRACE(c, (c, "Terminating TCP connection to {connstate}", conn))
304 #define TRACE_SENDTO_KDC_TCP_ERROR_CONNECT(c, conn, err) \
305 TRACE(c, (c, "TCP error connecting to {connstate}: {errno}", conn, err))
306 #define TRACE_SENDTO_KDC_TCP_ERROR_RECV(c, conn, err) \
307 TRACE(c, (c, "TCP error receiving from {connstate}: {errno}", conn, err))
308 #define TRACE_SENDTO_KDC_TCP_ERROR_RECV_LEN(c, conn, err) \
309 TRACE(c, (c, "TCP error receiving from {connstate}: {errno}", conn, err))
310 #define TRACE_SENDTO_KDC_TCP_ERROR_SEND(c, conn, err) \
311 TRACE(c, (c, "TCP error sending to {connstate}: {errno}", conn, err))
312 #define TRACE_SENDTO_KDC_TCP_SEND(c, conn) \
313 TRACE(c, (c, "Sending TCP request to {connstate}", conn))
314 #define TRACE_SENDTO_KDC_UDP_ERROR_RECV(c, conn, err) \
315 TRACE(c, (c, "UDP error receiving from {connstate}: {errno}", conn, err))
316 #define TRACE_SENDTO_KDC_UDP_ERROR_SEND_INITIAL(c, conn, err) \
317 TRACE(c, (c, "UDP error sending to {connstate}: {errno}", conn, err))
318 #define TRACE_SENDTO_KDC_UDP_ERROR_SEND_RETRY(c, conn, err) \
319 TRACE(c, (c, "UDP error sending to {connstate}: {errno}", conn, err))
320 #define TRACE_SENDTO_KDC_UDP_SEND_INITIAL(c, conn) \
321 TRACE(c, (c, "Sending initial UDP request to {connstate}", conn))
322 #define TRACE_SENDTO_KDC_UDP_SEND_RETRY(c, conn) \
323 TRACE(c, (c, "Sending retry UDP request to {connstate}", conn))
325 #define TRACE_SEND_TGS_ETYPES(c, etypes) \
326 TRACE(c, (c, "etypes requested in TGS request: {etypes}", etypes))
327 #define TRACE_SEND_TGS_SUBKEY(c, keyblock) \
328 TRACE(c, (c, "Generated subkey for TGS request: {keyblock}", keyblock))
330 #define TRACE_TGS_REPLY(c, client, server, keyblock) \
331 TRACE(c, (c, "TGS reply is for {princ} -> {princ} with session key " \
332 "{keyblock}", client, server, keyblock))
333 #define TRACE_TGS_REPLY_DECODE_SESSION(c, keyblock) \
334 TRACE(c, (c, "TGS reply didn't decode with subkey; trying session key " \
335 "({keyblock)}", keyblock))
337 #define TRACE_TKT_CREDS(c, creds, cache) \
338 TRACE(c, (c, "Getting credentials {creds} using ccache {ccache}", \
340 #define TRACE_TKT_CREDS_ADVANCE(c, realm) \
341 TRACE(c, (c, "Received TGT for {data}; advancing current realm", realm))
342 #define TRACE_TKT_CREDS_CACHED_INTERMEDIATE_TGT(c, tgt) \
343 TRACE(c, (c, "Found cached TGT for intermediate realm: {creds}", tgt))
344 #define TRACE_TKT_CREDS_CACHED_SERVICE_TGT(c, tgt) \
345 TRACE(c, (c, "Found cached TGT for service realm: {creds}", tgt))
346 #define TRACE_TKT_CREDS_CLOSER_REALM(c, realm) \
347 TRACE(c, (c, "Trying next closer realm in path: {data}", realm))
348 #define TRACE_TKT_CREDS_COMPLETE(c, princ) \
349 TRACE(c, (c, "Received creds for desired service {princ}", princ))
350 #define TRACE_TKT_CREDS_FALLBACK(c, realm) \
351 TRACE(c, (c, "Local realm referral failed; trying fallback realm {data}", \
353 #define TRACE_TKT_CREDS_LOCAL_TGT(c, tgt) \
354 TRACE(c, (c, "Starting with TGT for client realm: {creds}", tgt))
355 #define TRACE_TKT_CREDS_NON_TGT(c, princ) \
356 TRACE(c, (c, "Received non-TGT referral response ({princ}); trying " \
357 "again without referrals", princ))
358 #define TRACE_TKT_CREDS_OFFPATH(c, realm) \
359 TRACE(c, (c, "Received TGT for offpath realm {data}", realm))
360 #define TRACE_TKT_CREDS_REFERRAL(c, princ) \
361 TRACE(c, (c, "Following referral TGT {princ}", princ))
362 #define TRACE_TKT_CREDS_REFERRAL_REALM(c, princ) \
363 TRACE(c, (c, "Server has referral realm; starting with {princ}", princ))
364 #define TRACE_TKT_CREDS_RESPONSE_CODE(c, code) \
365 TRACE(c, (c, "TGS request result: {kerr}", code))
366 #define TRACE_TKT_CREDS_RETRY_TCP(c) \
367 TRACE(c, (c, "Request or response is too big for UDP; retrying with TCP"))
368 #define TRACE_TKT_CREDS_SAME_REALM_TGT(c, realm) \
369 TRACE(c, (c, "Received TGT referral back to same realm ({data}); trying " \
370 "again without referrals", realm))
371 #define TRACE_TKT_CREDS_SERVICE_REQ(c, princ, referral) \
372 TRACE(c, (c, "Requesting tickets for {princ}, referrals {str}", princ, \
373 (referral) ? "on" : "off"))
374 #define TRACE_TKT_CREDS_TARGET_TGT(c, princ) \
375 TRACE(c, (c, "Received TGT for service realm: {princ}", princ))
376 #define TRACE_TKT_CREDS_TARGET_TGT_OFFPATH(c, princ) \
377 TRACE(c, (c, "Received TGT for service realm: {princ}", princ))
378 #define TRACE_TKT_CREDS_TGT_REQ(c, next, cur) \
379 TRACE(c, (c, "Requesting TGT {princ} using TGT {princ}", next, cur))
380 #define TRACE_TKT_CREDS_WRONG_ENCTYPE(c) \
381 TRACE(c, (c, "Retrying TGS request with desired service ticket enctypes"))
383 #endif /* K5_TRACE_H */