From: Greg Hudson Date: Tue, 8 May 2012 03:04:22 +0000 (+0000) Subject: First pass at PKINIT client trace logs X-Git-Url: http://git.tremily.us/?a=commitdiff_plain;h=e785e6e2204c2cf1e262c92549fa6aea1c020ead;p=krb5.git First pass at PKINIT client trace logs Trace basic decisions about PKINIT client protocol processing. git-svn-id: svn://anonsvn.mit.edu/krb5/trunk@25855 dc483132-0cff-0310-8789-dd5450dbe970 --- diff --git a/src/plugins/preauth/pkinit/deps b/src/plugins/preauth/pkinit/deps index 3a6e43a84..fdef3441e 100644 --- a/src/plugins/preauth/pkinit/deps +++ b/src/plugins/preauth/pkinit/deps @@ -24,34 +24,39 @@ pkinit_srv.so pkinit_srv.po $(OUTPRE)pkinit_srv.$(OBJEXT): \ $(top_srcdir)/include/krb5/authdata_plugin.h $(top_srcdir)/include/krb5/plugin.h \ $(top_srcdir)/include/krb5/preauth_plugin.h $(top_srcdir)/include/port-sockets.h \ $(top_srcdir)/include/socket-utils.h pkcs11.h pkinit.h \ - pkinit_accessor.h pkinit_crypto.h pkinit_srv.c + pkinit_accessor.h pkinit_crypto.h pkinit_srv.c pkinit_trace.h pkinit_lib.so pkinit_lib.po $(OUTPRE)pkinit_lib.$(OBJEXT): \ $(BUILDTOP)/include/autoconf.h $(BUILDTOP)/include/krb5/krb5.h \ $(BUILDTOP)/include/profile.h $(COM_ERR_DEPS) $(top_srcdir)/include/k5-int-pkinit.h \ $(top_srcdir)/include/k5-platform.h $(top_srcdir)/include/k5-thread.h \ - $(top_srcdir)/include/krb5/plugin.h $(top_srcdir)/include/krb5/preauth_plugin.h \ - pkcs11.h pkinit.h pkinit_accessor.h pkinit_crypto.h \ - pkinit_lib.c + $(top_srcdir)/include/k5-trace.h $(top_srcdir)/include/krb5/plugin.h \ + $(top_srcdir)/include/krb5/preauth_plugin.h pkcs11.h \ + pkinit.h pkinit_accessor.h pkinit_crypto.h pkinit_lib.c \ + pkinit_trace.h pkinit_kdf_test.so pkinit_kdf_test.po $(OUTPRE)pkinit_kdf_test.$(OBJEXT): \ $(BUILDTOP)/include/autoconf.h $(BUILDTOP)/include/krb5/krb5.h \ $(BUILDTOP)/include/profile.h $(COM_ERR_DEPS) $(top_srcdir)/include/k5-int-pkinit.h \ $(top_srcdir)/include/k5-platform.h $(top_srcdir)/include/k5-thread.h \ - $(top_srcdir)/include/krb5/plugin.h $(top_srcdir)/include/krb5/preauth_plugin.h \ - pkcs11.h pkinit.h pkinit_accessor.h pkinit_crypto.h \ - pkinit_crypto_openssl.h pkinit_kdf_test.c + $(top_srcdir)/include/k5-trace.h $(top_srcdir)/include/krb5/plugin.h \ + $(top_srcdir)/include/krb5/preauth_plugin.h pkcs11.h \ + pkinit.h pkinit_accessor.h pkinit_crypto.h pkinit_crypto_openssl.h \ + pkinit_kdf_test.c pkinit_trace.h pkinit_kdf_constants.so pkinit_kdf_constants.po $(OUTPRE)pkinit_kdf_constants.$(OBJEXT): \ $(BUILDTOP)/include/autoconf.h $(BUILDTOP)/include/krb5/krb5.h \ $(BUILDTOP)/include/profile.h $(COM_ERR_DEPS) $(top_srcdir)/include/k5-int-pkinit.h \ $(top_srcdir)/include/k5-platform.h $(top_srcdir)/include/k5-thread.h \ - $(top_srcdir)/include/krb5.h $(top_srcdir)/include/krb5/plugin.h \ - $(top_srcdir)/include/krb5/preauth_plugin.h pkcs11.h \ - pkinit.h pkinit_accessor.h pkinit_crypto.h pkinit_kdf_constants.c + $(top_srcdir)/include/k5-trace.h $(top_srcdir)/include/krb5.h \ + $(top_srcdir)/include/krb5/plugin.h $(top_srcdir)/include/krb5/preauth_plugin.h \ + pkcs11.h pkinit.h pkinit_accessor.h pkinit_crypto.h \ + pkinit_kdf_constants.c pkinit_trace.h pkinit_clnt.so pkinit_clnt.po $(OUTPRE)pkinit_clnt.$(OBJEXT): \ $(BUILDTOP)/include/autoconf.h $(BUILDTOP)/include/krb5/krb5.h \ $(BUILDTOP)/include/profile.h $(COM_ERR_DEPS) $(top_srcdir)/include/k5-int-pkinit.h \ $(top_srcdir)/include/k5-platform.h $(top_srcdir)/include/k5-thread.h \ - $(top_srcdir)/include/krb5/plugin.h $(top_srcdir)/include/krb5/preauth_plugin.h \ - pkcs11.h pkinit.h pkinit_accessor.h pkinit_clnt.c pkinit_crypto.h + $(top_srcdir)/include/k5-trace.h $(top_srcdir)/include/krb5/plugin.h \ + $(top_srcdir)/include/krb5/preauth_plugin.h pkcs11.h \ + pkinit.h pkinit_accessor.h pkinit_clnt.c pkinit_crypto.h \ + pkinit_trace.h pkinit_profile.so pkinit_profile.po $(OUTPRE)pkinit_profile.$(OBJEXT): \ $(BUILDTOP)/include/autoconf.h $(BUILDTOP)/include/krb5/krb5.h \ $(BUILDTOP)/include/osconf.h $(BUILDTOP)/include/profile.h \ @@ -63,25 +68,29 @@ pkinit_profile.so pkinit_profile.po $(OUTPRE)pkinit_profile.$(OBJEXT): \ $(top_srcdir)/include/krb5/authdata_plugin.h $(top_srcdir)/include/krb5/plugin.h \ $(top_srcdir)/include/krb5/preauth_plugin.h $(top_srcdir)/include/port-sockets.h \ $(top_srcdir)/include/socket-utils.h pkcs11.h pkinit.h \ - pkinit_accessor.h pkinit_crypto.h pkinit_profile.c + pkinit_accessor.h pkinit_crypto.h pkinit_profile.c \ + pkinit_trace.h pkinit_identity.so pkinit_identity.po $(OUTPRE)pkinit_identity.$(OBJEXT): \ $(BUILDTOP)/include/autoconf.h $(BUILDTOP)/include/krb5/krb5.h \ $(BUILDTOP)/include/profile.h $(COM_ERR_DEPS) $(top_srcdir)/include/k5-int-pkinit.h \ $(top_srcdir)/include/k5-platform.h $(top_srcdir)/include/k5-thread.h \ - $(top_srcdir)/include/krb5/plugin.h $(top_srcdir)/include/krb5/preauth_plugin.h \ - pkcs11.h pkinit.h pkinit_accessor.h pkinit_crypto.h \ - pkinit_identity.c + $(top_srcdir)/include/k5-trace.h $(top_srcdir)/include/krb5/plugin.h \ + $(top_srcdir)/include/krb5/preauth_plugin.h pkcs11.h \ + pkinit.h pkinit_accessor.h pkinit_crypto.h pkinit_identity.c \ + pkinit_trace.h pkinit_matching.so pkinit_matching.po $(OUTPRE)pkinit_matching.$(OBJEXT): \ $(BUILDTOP)/include/autoconf.h $(BUILDTOP)/include/krb5/krb5.h \ $(BUILDTOP)/include/profile.h $(COM_ERR_DEPS) $(top_srcdir)/include/k5-int-pkinit.h \ $(top_srcdir)/include/k5-platform.h $(top_srcdir)/include/k5-thread.h \ - $(top_srcdir)/include/krb5/plugin.h $(top_srcdir)/include/krb5/preauth_plugin.h \ - pkcs11.h pkinit.h pkinit_accessor.h pkinit_crypto.h \ - pkinit_matching.c + $(top_srcdir)/include/k5-trace.h $(top_srcdir)/include/krb5/plugin.h \ + $(top_srcdir)/include/krb5/preauth_plugin.h pkcs11.h \ + pkinit.h pkinit_accessor.h pkinit_crypto.h pkinit_matching.c \ + pkinit_trace.h pkinit_crypto_openssl.so pkinit_crypto_openssl.po $(OUTPRE)pkinit_crypto_openssl.$(OBJEXT): \ $(BUILDTOP)/include/autoconf.h $(BUILDTOP)/include/krb5/krb5.h \ $(BUILDTOP)/include/profile.h $(COM_ERR_DEPS) $(top_srcdir)/include/k5-int-pkinit.h \ $(top_srcdir)/include/k5-platform.h $(top_srcdir)/include/k5-thread.h \ - $(top_srcdir)/include/krb5/plugin.h $(top_srcdir)/include/krb5/preauth_plugin.h \ - pkcs11.h pkinit.h pkinit_accessor.h pkinit_crypto.h \ - pkinit_crypto_openssl.c pkinit_crypto_openssl.h + $(top_srcdir)/include/k5-trace.h $(top_srcdir)/include/krb5/plugin.h \ + $(top_srcdir)/include/krb5/preauth_plugin.h pkcs11.h \ + pkinit.h pkinit_accessor.h pkinit_crypto.h pkinit_crypto_openssl.c \ + pkinit_crypto_openssl.h pkinit_trace.h diff --git a/src/plugins/preauth/pkinit/pkinit.h b/src/plugins/preauth/pkinit/pkinit.h index 53e9abd7b..62df7edea 100644 --- a/src/plugins/preauth/pkinit/pkinit.h +++ b/src/plugins/preauth/pkinit/pkinit.h @@ -38,6 +38,7 @@ #include #include #include "pkinit_accessor.h" +#include "pkinit_trace.h" /* * It is anticipated that all the special checks currently diff --git a/src/plugins/preauth/pkinit/pkinit_clnt.c b/src/plugins/preauth/pkinit/pkinit_clnt.c index 806cd75f5..4a27902f3 100644 --- a/src/plugins/preauth/pkinit/pkinit_clnt.c +++ b/src/plugins/preauth/pkinit/pkinit_clnt.c @@ -138,6 +138,7 @@ pa_pkinit_gen_req(krb5_context context, der_req, &cksum); if (retval) goto cleanup; + TRACE_PKINIT_CLIENT_REQ_CHECKSUM(context, &cksum); #ifdef DEBUG_CKSUM pkiDebug("calculating checksum on buf size (%d)\n", der_req->length); print_buffer(der_req->data, der_req->length); @@ -293,6 +294,7 @@ pkinit_as_req_create(krb5_context context, switch(protocol) { case DH_PROTOCOL: + TRACE_PKINIT_CLIENT_REQ_DH(context); pkiDebug("as_req: DH key transport algorithm\n"); retval = pkinit_copy_krb5_data(&info->algorithm.algorithm, &dh_oid); if (retval) { @@ -314,6 +316,7 @@ pkinit_as_req_create(krb5_context context, } break; case RSA_PROTOCOL: + TRACE_PKINIT_CLIENT_REQ_RSA(context); pkiDebug("as_req: RSA key transport algorithm\n"); switch((int)reqctx->pa_type) { case KRB5_PADATA_PK_AS_REQ_OLD: @@ -517,8 +520,8 @@ verify_kdc_san(krb5_context context, int *need_eku_checking) { krb5_error_code retval; - char **certhosts = NULL, **cfghosts = NULL; - krb5_principal *princs = NULL; + char **certhosts = NULL, **cfghosts = NULL, **hostptr; + krb5_principal *princs = NULL, *princptr; unsigned char ***get_dns; int i, j; @@ -536,6 +539,8 @@ verify_kdc_san(krb5_context context, } else { pkiDebug("%s: pkinit_kdc_hostname values found in config file\n", __FUNCTION__); + for (hostptr = cfghosts; *hostptr != NULL; hostptr++) + TRACE_PKINIT_CLIENT_SAN_CONFIG_DNSNAME(context, *hostptr); get_dns = (unsigned char ***)&certhosts; } @@ -544,9 +549,16 @@ verify_kdc_san(krb5_context context, &princs, NULL, get_dns); if (retval) { pkiDebug("%s: error from retrieve_certificate_sans()\n", __FUNCTION__); + TRACE_PKINIT_CLIENT_SAN_ERR(context); retval = KRB5KDC_ERR_KDC_NAME_MISMATCH; goto out; } + for (princptr = princs; *princptr != NULL; princptr++) + TRACE_PKINIT_CLIENT_SAN_KDCCERT_PRINC(context, *princptr); + if (certhosts != NULL) { + for (hostptr = certhosts; *hostptr != NULL; hostptr++) + TRACE_PKINIT_CLIENT_SAN_KDCCERT_DNSNAME(context, *hostptr); + } #if 0 retval = call_san_checking_plugins(context, plgctx, reqctx, idctx, princs, hosts, &plugin_decision, @@ -569,6 +581,7 @@ verify_kdc_san(krb5_context context, pkiDebug("%s: Checking pkinit sans\n", __FUNCTION__); for (i = 0; princs != NULL && princs[i] != NULL; i++) { if (krb5_principal_compare(context, princs[i], kdcprinc)) { + TRACE_PKINIT_CLIENT_SAN_MATCH_PRINC(context, kdcprinc); pkiDebug("%s: pkinit san match found\n", __FUNCTION__); *valid_san = 1; *need_eku_checking = 0; @@ -590,6 +603,7 @@ verify_kdc_san(krb5_context context, pkiDebug("%s: comparing cert name '%s' with config name '%s'\n", __FUNCTION__, certhosts[i], cfghosts[j]); if (strcmp(certhosts[i], cfghosts[j]) == 0) { + TRACE_PKINIT_CLIENT_SAN_MATCH_DNSNAME(context, certhosts[i]); pkiDebug("%s: we have a dnsName match\n", __FUNCTION__); *valid_san = 1; retval = 0; @@ -597,6 +611,7 @@ verify_kdc_san(krb5_context context, } } } + TRACE_PKINIT_CLIENT_SAN_MATCH_NONE(context); pkiDebug("%s: no dnsName san match found\n", __FUNCTION__); /* We found no match */ @@ -632,6 +647,7 @@ verify_kdc_eku(krb5_context context, *eku_accepted = 0; if (reqctx->opts->require_eku == 0) { + TRACE_PKINIT_CLIENT_EKU_SKIP(context); pkiDebug("%s: configuration requests no EKU checking\n", __FUNCTION__); *eku_accepted = 1; retval = 0; @@ -649,6 +665,10 @@ verify_kdc_eku(krb5_context context, } out: + if (eku_accepted) + TRACE_PKINIT_CLIENT_EKU_ACCEPT(context); + else + TRACE_PKINIT_CLIENT_EKU_REJECT(context); pkiDebug("%s: returning retval %d, eku_accepted %d\n", __FUNCTION__, retval, *eku_accepted); return retval; @@ -715,9 +735,10 @@ pkinit_as_rep_parse(krb5_context context, &dh_data.length, NULL, NULL, NULL)) != 0) { pkiDebug("failed to verify pkcs7 signed data\n"); + TRACE_PKINIT_CLIENT_REP_DH_FAIL(context); goto cleanup; } - + TRACE_PKINIT_CLIENT_REP_DH(context); break; case choice_pa_pk_as_rep_encKeyPack: pkiDebug("as_rep: RSA key transport algorithm\n"); @@ -730,8 +751,10 @@ pkinit_as_rep_parse(krb5_context context, (unsigned char **)&dh_data.data, &dh_data.length)) != 0) { pkiDebug("failed to verify pkcs7 enveloped data\n"); + TRACE_PKINIT_CLIENT_REP_RSA_FAIL(context); goto cleanup; } + TRACE_PKINIT_CLIENT_REP_RSA(context); break; default: pkiDebug("unknown as_rep type %d\n", kdc_reply->choice); @@ -813,6 +836,8 @@ pkinit_as_rep_parse(krb5_context context, error_message(retval)); goto cleanup; } + TRACE_PKINIT_CLIENT_KDF_ALG(context, kdc_reply->u.dh_Info.kdfID, + key_block); /* ...otherwise, use the older octetstring2key function. */ } else { @@ -824,6 +849,7 @@ pkinit_as_rep_parse(krb5_context context, error_message(retval)); goto cleanup; } + TRACE_PKINIT_CLIENT_KDF_OS2K(context, key_block); } break; @@ -884,6 +910,8 @@ pkinit_as_rep_parse(krb5_context context, if ((cksum.length != key_pack->asChecksum.length) || memcmp(cksum.contents, key_pack->asChecksum.contents, cksum.length)) { + TRACE_PKINIT_CLIENT_REP_CHECKSUM_FAIL(context, &cksum, + &key_pack->asChecksum); pkiDebug("failed to match the checksums\n"); #ifdef DEBUG_CKSUM pkiDebug("calculating checksum on buf size (%d)\n", @@ -907,6 +935,7 @@ pkinit_as_rep_parse(krb5_context context, krb5_copy_keyblock_contents(context, &key_pack->replyKey, key_block); + TRACE_PKINIT_CLIENT_REP_RSA_KEY(context, key_block, &cksum); break; default: @@ -1076,6 +1105,7 @@ pkinit_client_process(krb5_context context, krb5_clpreauth_moddata moddata, reqctx->cryptoctx, reqctx->idopts, reqctx->idctx, 1, request->client); if (retval) { + TRACE_PKINIT_CLIENT_NO_IDENTITY(context); pkiDebug("pkinit_identity_initialize returned %d (%s)\n", retval, error_message(retval)); return retval; @@ -1166,6 +1196,7 @@ pkinit_client_tryagain(krb5_context context, krb5_clpreauth_moddata moddata, } if (do_again) { + TRACE_PKINIT_CLIENT_TRYAGAIN(context); retval = pa_pkinit_gen_req(context, plgctx, reqctx, request, pa_type, out_padata, prompter, prompter_data, gic_opt); diff --git a/src/plugins/preauth/pkinit/pkinit_trace.h b/src/plugins/preauth/pkinit/pkinit_trace.h new file mode 100644 index 000000000..15c14ca96 --- /dev/null +++ b/src/plugins/preauth/pkinit/pkinit_trace.h @@ -0,0 +1,90 @@ +/* -*- mode: c; c-basic-offset: 4; indent-tabs-mode: nil -*- */ +/* plugins/preauth/pkinit/pkinit_trace.h - PKINIT tracing macros */ +/* + * Copyright (C) 2012 by the Massachusetts Institute of Technology. + * All rights reserved. + * + * Redistribution and use in source and binary forms, with or without + * modification, are permitted provided that the following conditions + * are met: + * + * * Redistributions of source code must retain the above copyright + * notice, this list of conditions and the following disclaimer. + * + * * Redistributions in binary form must reproduce the above copyright + * notice, this list of conditions and the following disclaimer in + * the documentation and/or other materials provided with the + * distribution. + * + * THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS + * "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT + * LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS + * FOR A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE + * COPYRIGHT HOLDER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, + * INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES + * (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR + * SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION) + * HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, + * STRICT LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) + * ARISING IN ANY WAY OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED + * OF THE POSSIBILITY OF SUCH DAMAGE. + */ + +#ifndef PKINIT_TRACE_H +#define PKINIT_TRACE_H + +#include "k5-trace.h" + +#define TRACE_PKINIT_CLIENT_EKU_ACCEPT(c) \ + TRACE(c, "PKINIT client found acceptable EKU in KDC cert") +#define TRACE_PKINIT_CLIENT_EKU_REJECT(c) \ + TRACE(c, "PKINIT client found no acceptable EKU in KDC cert") +#define TRACE_PKINIT_CLIENT_EKU_SKIP(c) \ + TRACE(c, "PKINIT client skipping EKU check due to configuration") +#define TRACE_PKINIT_CLIENT_KDF_ALG(c, kdf, keyblock) \ + TRACE(c, "PKINIT client used KDF {hexdata} to compute reply key " \ + "{keyblock}", kdf, keyblock) +#define TRACE_PKINIT_CLIENT_KDF_OS2K(c, keyblock) \ + TRACE(c, "PKINIT client used octetstring2key to compute reply key " \ + "{keyblock}", keyblock) +#define TRACE_PKINIT_CLIENT_NO_IDENTITY(c) \ + TRACE(c, "PKINIT client has no configured identity; giving up") +#define TRACE_PKINIT_CLIENT_REP_CHECKSUM_FAIL(c, expected, received) \ + TRACE(c, "PKINIT client checksum mismatch: expected {cksum}, " \ + "received {cksum}", expected, received) +#define TRACE_PKINIT_CLIENT_REP_DH(c) \ + TRACE(c, "PKINIT client verified DH reply") +#define TRACE_PKINIT_CLIENT_REP_DH_FAIL(c) \ + TRACE(c, "PKINIT client could not verify DH reply") +#define TRACE_PKINIT_CLIENT_REP_RSA(c) \ + TRACE(c, "PKINIT client verified RSA reply") +#define TRACE_PKINIT_CLIENT_REP_RSA_KEY(c, keyblock, cksum) \ + TRACE(c, "PKINIT client retrieved reply key {keyblock} from RSA " \ + "reply (checksum {cksum})", keyblock, cksum) +#define TRACE_PKINIT_CLIENT_REP_RSA_FAIL(c) \ + TRACE(c, "PKINIT client could not verify RSA reply") +#define TRACE_PKINIT_CLIENT_REQ_CHECKSUM(c, cksum) \ + TRACE(c, "PKINIT client computed kdc-req-body checksum {cksum}", cksum) +#define TRACE_PKINIT_CLIENT_REQ_DH(c) \ + TRACE(c, "PKINIT client making DH request") +#define TRACE_PKINIT_CLIENT_REQ_RSA(c) \ + TRACE(c, "PKINIT client making RSA request") +#define TRACE_PKINIT_CLIENT_SAN_CONFIG_DNSNAME(c, host) \ + TRACE(c, "PKINIT client config accepts KDC dNSName SAN {string}", host) +#define TRACE_PKINIT_CLIENT_SAN_MATCH_DNSNAME(c, host) \ + TRACE(c, "PKINIT client matched KDC hostname {string} against " \ + "dNSName SAN; EKU check still required", host) +#define TRACE_PKINIT_CLIENT_SAN_MATCH_NONE(c) \ + TRACE(c, "PKINIT client found no acceptable SAN in KDC cert") +#define TRACE_PKINIT_CLIENT_SAN_MATCH_PRINC(c, princ) \ + TRACE(c, "PKINIT client matched KDC principal {princ} against " \ + "id-pkinit-san; no EKU check required", princ) +#define TRACE_PKINIT_CLIENT_SAN_ERR(c) \ + TRACE(c, "PKINIT client failed to decode SANs in KDC cert") +#define TRACE_PKINIT_CLIENT_SAN_KDCCERT_DNSNAME(c, host) \ + TRACE(c, "PKINIT client found dNSName SAN in KDC cert: {string}", host) +#define TRACE_PKINIT_CLIENT_SAN_KDCCERT_PRINC(c, princ) \ + TRACE(c, "PKINIT client found id-pkinit-san in KDC cert: {princ}", princ) +#define TRACE_PKINIT_CLIENT_TRYAGAIN(c) \ + TRACE(c, "PKINIT client trying again with KDC-provided parameters") +#endif /* PKINIT_TRACE_H */