From caa480251ebdebbc5c9093223267cf5634493b03 Mon Sep 17 00:00:00 2001 From: Greg Hudson Date: Mon, 7 Jun 2010 18:26:17 +0000 Subject: Trace logging Add trace logging infrastructure code, enabled by the KRB5_TRACE environment variable or the API functions krb5_set_trace_callback() or krb5_set_trace_filename(). As a start, add tracing events for: * AS-REQ client code, including FAST and preauth * TGS-REQ client code * AP-REQ and AP-REP code (client and server) * sendto_kdc * Selected ccache operations * Selected keytab operations ticket: 6737 git-svn-id: svn://anonsvn.mit.edu/krb5/trunk@24118 dc483132-0cff-0310-8789-dd5450dbe970 --- src/lib/krb5/ccache/ccbase.c | 2 + src/lib/krb5/ccache/ccfns.c | 12 ++ src/lib/krb5/error_tables/krb5_err.et | 2 + src/lib/krb5/keytab/ktfns.c | 1 + src/lib/krb5/krb/fast.c | 20 +- src/lib/krb5/krb/gc_via_tkt.c | 3 + src/lib/krb5/krb/get_creds.c | 33 ++- src/lib/krb5/krb/get_in_tkt.c | 38 +++- src/lib/krb5/krb/gic_pwd.c | 4 + src/lib/krb5/krb/init_ctx.c | 11 +- src/lib/krb5/krb/mk_rep.c | 3 + src/lib/krb5/krb/mk_req_ext.c | 6 +- src/lib/krb5/krb/preauth2.c | 60 ++---- src/lib/krb5/krb/rd_rep.c | 5 + src/lib/krb5/krb/rd_req_dec.c | 9 + src/lib/krb5/krb/send_tgs.c | 2 + src/lib/krb5/libkrb5.exports | 2 + src/lib/krb5/os/Makefile.in | 3 + src/lib/krb5/os/sendto_kdc.c | 72 ++++--- src/lib/krb5/os/trace.c | 368 ++++++++++++++++++++++++++++++++++ 20 files changed, 568 insertions(+), 88 deletions(-) create mode 100644 src/lib/krb5/os/trace.c (limited to 'src/lib') diff --git a/src/lib/krb5/ccache/ccbase.c b/src/lib/krb5/ccache/ccbase.c index 023c7b158f..ab163b3d1b 100644 --- a/src/lib/krb5/ccache/ccbase.c +++ b/src/lib/krb5/ccache/ccbase.c @@ -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; diff --git a/src/lib/krb5/ccache/ccfns.c b/src/lib/krb5/ccache/ccfns.c index 088fdf6e36..01acd22f22 100644 --- a/src/lib/krb5/ccache/ccfns.c +++ b/src/lib/krb5/ccache/ccfns.c @@ -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); diff --git a/src/lib/krb5/error_tables/krb5_err.et b/src/lib/krb5/error_tables/krb5_err.et index 56434ad479..b771122d78 100644 --- a/src/lib/krb5/error_tables/krb5_err.et +++ b/src/lib/krb5/error_tables/krb5_err.et @@ -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 diff --git a/src/lib/krb5/keytab/ktfns.c b/src/lib/krb5/keytab/ktfns.c index 3496c09647..33c91844d1 100644 --- a/src/lib/krb5/keytab/ktfns.c +++ b/src/lib/krb5/keytab/ktfns.c @@ -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; diff --git a/src/lib/krb5/krb/fast.c b/src/lib/krb5/krb/fast.c index 30be3818c9..50321cc86c 100644 --- a/src/lib/krb5/krb/fast.c +++ b/src/lib/krb5/krb/fast.c @@ -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; } diff --git a/src/lib/krb5/krb/gc_via_tkt.c b/src/lib/krb5/krb/gc_via_tkt.c index 0ab421383f..5bee608a73 100644 --- a/src/lib/krb5/krb/gc_via_tkt.c +++ b/src/lib/krb5/krb/gc_via_tkt.c @@ -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) diff --git a/src/lib/krb5/krb/get_creds.c b/src/lib/krb5/krb/get_creds.c index 0e4956e262..eb96a2df29 100644 --- a/src/lib/krb5/krb/get_creds.c +++ b/src/lib/krb5/krb/get_creds.c @@ -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); diff --git a/src/lib/krb5/krb/get_in_tkt.c b/src/lib/krb5/krb/get_in_tkt.c index 63402ca032..28a23f2c43 100644 --- a/src/lib/krb5/krb/get_in_tkt.c +++ b/src/lib/krb5/krb/get_in_tkt.c @@ -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); diff --git a/src/lib/krb5/krb/gic_pwd.c b/src/lib/krb5/krb/gic_pwd.c index 7b437272f8..6df9014986 100644 --- a/src/lib/krb5/krb/gic_pwd.c +++ b/src/lib/krb5/krb/gic_pwd.c @@ -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, diff --git a/src/lib/krb5/krb/init_ctx.c b/src/lib/krb5/krb/init_ctx.c index e72534cccb..e7419f5d4a 100644 --- a/src/lib/krb5/krb/init_ctx.c +++ b/src/lib/krb5/krb/init_ctx.c @@ -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); } diff --git a/src/lib/krb5/krb/mk_rep.c b/src/lib/krb5/krb/mk_rep.c index b50c057654..af024042b6 100644 --- a/src/lib/krb5/krb/mk_rep.c +++ b/src/lib/krb5/krb/mk_rep.c @@ -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; diff --git a/src/lib/krb5/krb/mk_req_ext.c b/src/lib/krb5/krb/mk_req_ext.c index 554dda360a..3a4004dc08 100644 --- a/src/lib/krb5/krb/mk_req_ext.c +++ b/src/lib/krb5/krb/mk_req_ext.c @@ -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) diff --git a/src/lib/krb5/krb/preauth2.c b/src/lib/krb5/krb/preauth2.c index ce8d10536e..c07fc46da7 100644 --- a/src/lib/krb5/krb/preauth2.c +++ b/src/lib/krb5/krb/preauth2.c @@ -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); diff --git a/src/lib/krb5/krb/rd_rep.c b/src/lib/krb5/krb/rd_rep.c index 45c9901875..2fdb2a04ac 100644 --- a/src/lib/krb5/krb/rd_rep.c +++ b/src/lib/krb5/krb/rd_rep.c @@ -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); diff --git a/src/lib/krb5/krb/rd_req_dec.c b/src/lib/krb5/krb/rd_req_dec.c index 21728a5279..014002981b 100644 --- a/src/lib/krb5/krb/rd_req_dec.c +++ b/src/lib/krb5/krb/rd_req_dec.c @@ -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)))) diff --git a/src/lib/krb5/krb/send_tgs.c b/src/lib/krb5/krb/send_tgs.c index 83cc2158d6..41ab4ec61f 100644 --- a/src/lib/krb5/krb/send_tgs.c +++ b/src/lib/krb5/krb/send_tgs.c @@ -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))) diff --git a/src/lib/krb5/libkrb5.exports b/src/lib/krb5/libkrb5.exports index 8ed5441af5..2bd597204b 100644 --- a/src/lib/krb5/libkrb5.exports +++ b/src/lib/krb5/libkrb5.exports @@ -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 diff --git a/src/lib/krb5/os/Makefile.in b/src/lib/krb5/os/Makefile.in index 6a1ffd13fd..0852e144b6 100644 --- a/src/lib/krb5/os/Makefile.in +++ b/src/lib/krb5/os/Makefile.in @@ -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 diff --git a/src/lib/krb5/os/sendto_kdc.c b/src/lib/krb5/os/sendto_kdc.c index 341afe891c..4cdffe716a 100644 --- a/src/lib/krb5/os/sendto_kdc.c +++ b/src/lib/krb5/os/sendto_kdc.c @@ -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 index 0000000000..8db9c505af --- /dev/null +++ b/src/lib/krb5/os/trace.c @@ -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 */ -- cgit