From 7564be02d140b5caa225679c8f728ee49d9a9e0a Mon Sep 17 00:00:00 2001 From: Matt Rogers Date: Wed, 29 Mar 2017 10:35:13 -0400 Subject: [PATCH] Convert some pkiDebug messages to TRACE macros ticket: 8568 (new) (cherry picked from commit 9852862a83952a94300adfafa3e333f43396ec33) (cherry picked from commit 686fa6476eb759532d566794fa8d430774d44cf7) --- .../preauth/pkinit/pkinit_crypto_openssl.c | 46 +++++-------- src/plugins/preauth/pkinit/pkinit_identity.c | 3 - src/plugins/preauth/pkinit/pkinit_matching.c | 1 + src/plugins/preauth/pkinit/pkinit_srv.c | 24 +++---- src/plugins/preauth/pkinit/pkinit_trace.h | 68 ++++++++++++++++++- 5 files changed, 97 insertions(+), 45 deletions(-) diff --git a/src/plugins/preauth/pkinit/pkinit_crypto_openssl.c b/src/plugins/preauth/pkinit/pkinit_crypto_openssl.c index a5b010b26..792a2f771 100644 --- a/src/plugins/preauth/pkinit/pkinit_crypto_openssl.c +++ b/src/plugins/preauth/pkinit/pkinit_crypto_openssl.c @@ -2320,7 +2320,6 @@ crypto_check_cert_eku(krb5_context context, X509_NAME_oneline(X509_get_subject_name(reqctx->received_cert), buf, sizeof(buf)); - pkiDebug("%s: looking for EKUs in cert = %s\n", __FUNCTION__, buf); if ((i = X509_get_ext_by_NID(reqctx->received_cert, NID_ext_key_usage, -1)) >= 0) { @@ -2354,7 +2353,6 @@ crypto_check_cert_eku(krb5_context context, if (found_eku) { ASN1_BIT_STRING *usage = NULL; - pkiDebug("%s: found acceptable EKU, checking for digitalSignature\n", __FUNCTION__); /* check that digitalSignature KeyUsage is present */ X509_check_ca(reqctx->received_cert); @@ -2363,12 +2361,10 @@ crypto_check_cert_eku(krb5_context context, if (!ku_reject(reqctx->received_cert, X509v3_KU_DIGITAL_SIGNATURE)) { - pkiDebug("%s: found digitalSignature KU\n", - __FUNCTION__); + TRACE_PKINIT_EKU(context); *valid_eku = 1; } else - pkiDebug("%s: didn't find digitalSignature KU\n", - __FUNCTION__); + TRACE_PKINIT_EKU_NO_KU(context); } ASN1_BIT_STRING_free(usage); } @@ -4317,8 +4313,7 @@ pkinit_get_certs_pkcs12(krb5_context context, fp = fopen(idopts->cert_filename, "rb"); if (fp == NULL) { - pkiDebug("Failed to open PKCS12 file '%s', error %d\n", - idopts->cert_filename, errno); + TRACE_PKINIT_PKCS_OPEN_FAIL(context, idopts->cert_filename, errno); goto cleanup; } set_cloexec_file(fp); @@ -4326,8 +4321,7 @@ pkinit_get_certs_pkcs12(krb5_context context, p12 = d2i_PKCS12_fp(fp, NULL); fclose(fp); if (p12 == NULL) { - pkiDebug("Failed to decode PKCS12 file '%s' contents\n", - idopts->cert_filename); + TRACE_PKINIT_PKCS_DECODE_FAIL(context, idopts->cert_filename); goto cleanup; } /* @@ -4345,7 +4339,7 @@ pkinit_get_certs_pkcs12(krb5_context context, char *p12name = reassemble_pkcs12_name(idopts->cert_filename); const char *tmp; - pkiDebug("Initial PKCS12_parse with no password failed\n"); + TRACE_PKINIT_PKCS_PARSE_FAIL_FIRST(context); if (id_cryptoctx->defer_id_prompt) { /* Supply the identity name to be passed to the responder. */ @@ -4386,14 +4380,14 @@ pkinit_get_certs_pkcs12(krb5_context context, NULL, NULL, 1, &kprompt); k5int_set_prompt_types(context, 0); if (r) { - pkiDebug("Failed to prompt for PKCS12 password"); + TRACE_PKINIT_PKCS_PROMPT_FAIL(context); goto cleanup; } } ret = PKCS12_parse(p12, rdat.data, &y, &x, NULL); if (ret == 0) { - pkiDebug("Second PKCS12_parse with password failed\n"); + TRACE_PKINIT_PKCS_PARSE_FAIL_SECOND(context); goto cleanup; } } @@ -4516,8 +4510,7 @@ pkinit_get_certs_fs(krb5_context context, } if (idopts->key_filename == NULL) { - pkiDebug("%s: failed to get user's private key location\n", - __FUNCTION__); + TRACE_PKINIT_NO_PRIVKEY(context); goto cleanup; } @@ -4545,8 +4538,7 @@ pkinit_get_certs_dir(krb5_context context, char *dirname, *suf; if (idopts->cert_filename == NULL) { - pkiDebug("%s: failed to get user's certificate directory location\n", - __FUNCTION__); + TRACE_PKINIT_NO_CERT(context); return ENOENT; } @@ -4590,8 +4582,7 @@ pkinit_get_certs_dir(krb5_context context, retval = pkinit_load_fs_cert_and_key(context, id_cryptoctx, certname, keyname, i); if (retval == 0) { - pkiDebug("%s: Successfully loaded cert (and key) for %s\n", - __FUNCTION__, dentry->d_name); + TRACE_PKINIT_LOADED_CERT(context, dentry->d_name); i++; } else @@ -4599,8 +4590,7 @@ pkinit_get_certs_dir(krb5_context context, } if (!id_cryptoctx->defer_id_prompt && i == 0) { - pkiDebug("%s: No cert/key pairs found in directory '%s'\n", - __FUNCTION__, idopts->cert_filename); + TRACE_PKINIT_NO_CERT_AND_KEY(context, idopts->cert_filename); retval = ENOENT; goto cleanup; } @@ -5370,9 +5360,7 @@ crypto_cert_select_default(krb5_context context, goto errout; } if (cert_count != 1) { - pkiDebug("%s: ERROR: There are %d certs to choose from, " - "but there must be exactly one.\n", - __FUNCTION__, cert_count); + TRACE_PKINIT_NO_DEFAULT_CERT(context, cert_count); retval = EINVAL; goto errout; } @@ -5520,7 +5508,7 @@ load_cas_and_crls(krb5_context context, switch(catype) { case CATYPE_ANCHORS: if (sk_X509_num(ca_certs) == 0) { - pkiDebug("no anchors in file, %s\n", filename); + TRACE_PKINIT_NO_CA_ANCHOR(context, filename); if (id_cryptoctx->trustedCAs == NULL) sk_X509_free(ca_certs); } else { @@ -5530,7 +5518,7 @@ load_cas_and_crls(krb5_context context, break; case CATYPE_INTERMEDIATES: if (sk_X509_num(ca_certs) == 0) { - pkiDebug("no intermediates in file, %s\n", filename); + TRACE_PKINIT_NO_CA_INTERMEDIATE(context, filename); if (id_cryptoctx->intermediateCAs == NULL) sk_X509_free(ca_certs); } else { @@ -5540,7 +5528,7 @@ load_cas_and_crls(krb5_context context, break; case CATYPE_CRLS: if (sk_X509_CRL_num(ca_crls) == 0) { - pkiDebug("no crls in file, %s\n", filename); + TRACE_PKINIT_NO_CRL(context, filename); if (id_cryptoctx->revoked == NULL) sk_X509_CRL_free(ca_crls); } else { @@ -5626,14 +5614,14 @@ crypto_load_cas_and_crls(krb5_context context, int catype, char *id) { - pkiDebug("%s: called with idtype %s and catype %s\n", - __FUNCTION__, idtype2string(idtype), catype2string(catype)); switch (idtype) { case IDTYPE_FILE: + TRACE_PKINIT_LOAD_FROM_FILE(context); return load_cas_and_crls(context, plg_cryptoctx, req_cryptoctx, id_cryptoctx, catype, id); break; case IDTYPE_DIR: + TRACE_PKINIT_LOAD_FROM_DIR(context); return load_cas_and_crls_dir(context, plg_cryptoctx, req_cryptoctx, id_cryptoctx, catype, id); break; diff --git a/src/plugins/preauth/pkinit/pkinit_identity.c b/src/plugins/preauth/pkinit/pkinit_identity.c index a897efa25..737552e85 100644 --- a/src/plugins/preauth/pkinit/pkinit_identity.c +++ b/src/plugins/preauth/pkinit/pkinit_identity.c @@ -608,7 +608,6 @@ pkinit_identity_prompt(krb5_context context, retval = pkinit_cert_matching(context, plg_cryptoctx, req_cryptoctx, id_cryptoctx, princ); if (retval) { - pkiDebug("%s: No matching certificate found\n", __FUNCTION__); crypto_free_cert_info(context, plg_cryptoctx, req_cryptoctx, id_cryptoctx); goto errout; @@ -621,8 +620,6 @@ pkinit_identity_prompt(krb5_context context, retval = crypto_cert_select_default(context, plg_cryptoctx, req_cryptoctx, id_cryptoctx); if (retval) { - pkiDebug("%s: Failed while selecting default certificate\n", - __FUNCTION__); crypto_free_cert_info(context, plg_cryptoctx, req_cryptoctx, id_cryptoctx); goto errout; diff --git a/src/plugins/preauth/pkinit/pkinit_matching.c b/src/plugins/preauth/pkinit/pkinit_matching.c index a50c50c8d..cad4c2b9a 100644 --- a/src/plugins/preauth/pkinit/pkinit_matching.c +++ b/src/plugins/preauth/pkinit/pkinit_matching.c @@ -812,6 +812,7 @@ pkinit_cert_matching(krb5_context context, goto cleanup; } } else { + TRACE_PKINIT_NO_MATCHING_CERT(context); retval = ENOENT; /* XXX */ goto cleanup; } diff --git a/src/plugins/preauth/pkinit/pkinit_srv.c b/src/plugins/preauth/pkinit/pkinit_srv.c index 32ca122f2..9c6e96c9e 100644 --- a/src/plugins/preauth/pkinit/pkinit_srv.c +++ b/src/plugins/preauth/pkinit/pkinit_srv.c @@ -188,6 +188,7 @@ verify_client_san(krb5_context context, plgctx->opts->allow_upn ? &upns : NULL, NULL); if (retval == ENOENT) { + TRACE_PKINIT_SERVER_NO_SAN(context); goto out; } else if (retval) { pkiDebug("%s: error from retrieve_certificate_sans()\n", __FUNCTION__); @@ -224,7 +225,7 @@ verify_client_san(krb5_context context, krb5_free_unparsed_name(context, san_string); #endif if (cb->match_client(context, rock, princs[i])) { - pkiDebug("%s: pkinit san match found\n", __FUNCTION__); + TRACE_PKINIT_SERVER_MATCHING_SAN_FOUND(context); *valid_san = 1; retval = 0; goto out; @@ -252,7 +253,7 @@ verify_client_san(krb5_context context, krb5_free_unparsed_name(context, san_string); #endif if (cb->match_client(context, rock, upns[i])) { - pkiDebug("%s: upn san match found\n", __FUNCTION__); + TRACE_PKINIT_SERVER_MATCHING_UPN_FOUND(context); *valid_san = 1; retval = 0; goto out; @@ -300,7 +301,7 @@ verify_client_eku(krb5_context context, *eku_accepted = 0; if (plgctx->opts->require_eku == 0) { - pkiDebug("%s: configuration requests no EKU checking\n", __FUNCTION__); + TRACE_PKINIT_SERVER_EKU_SKIP(context); *eku_accepted = 1; retval = 0; goto out; @@ -364,6 +365,7 @@ authorize_cert(krb5_context context, certauth_handle *certauth_modules, ret = KRB5_PLUGIN_NO_HANDLE; for (i = 0; certauth_modules != NULL && certauth_modules[i] != NULL; i++) { h = certauth_modules[i]; + TRACE_PKINIT_SERVER_CERT_AUTH(context, h->vt.name); ret = h->vt.authorize(context, h->moddata, cert, cert_len, client, &opts, db_ent, &ais); if (ret == 0) @@ -449,7 +451,7 @@ pkinit_server_verify_padata(krb5_context context, switch ((int)data->pa_type) { case KRB5_PADATA_PK_AS_REQ: - pkiDebug("processing KRB5_PADATA_PK_AS_REQ\n"); + TRACE_PKINIT_SERVER_PADATA_VERIFY(context); retval = k5int_decode_krb5_pa_pk_as_req(&k5data, &reqp); if (retval) { pkiDebug("decode_krb5_pa_pk_as_req failed\n"); @@ -472,7 +474,7 @@ pkinit_server_verify_padata(krb5_context context, break; case KRB5_PADATA_PK_AS_REP_OLD: case KRB5_PADATA_PK_AS_REQ_OLD: - pkiDebug("processing KRB5_PADATA_PK_AS_REQ_OLD\n"); + TRACE_PKINIT_SERVER_PADATA_VERIFY_OLD(context); retval = k5int_decode_krb5_pa_pk_as_req_draft9(&k5data, &reqp9); if (retval) { pkiDebug("decode_krb5_pa_pk_as_req_draft9 failed\n"); @@ -500,7 +502,7 @@ pkinit_server_verify_padata(krb5_context context, goto cleanup; } if (retval) { - pkiDebug("pkcs7_signeddata_verify failed\n"); + TRACE_PKINIT_SERVER_PADATA_VERIFY_FAIL(context); goto cleanup; } if (is_signed) { @@ -830,7 +832,7 @@ pkinit_server_return_padata(krb5_context context, return ENOENT; } - pkiDebug("pkinit_return_padata: entered!\n"); + TRACE_PKINIT_SERVER_RETURN_PADATA(context); reqctx = (pkinit_kdc_req_context)modreq; if (encrypting_key->contents) { @@ -1463,8 +1465,7 @@ pkinit_san_authorize(krb5_context context, krb5_certauth_moddata moddata, return ret; if (!valid_san) { - pkiDebug("%s: did not find an acceptable SAN in user certificate\n", - __FUNCTION__); + TRACE_PKINIT_SERVER_SAN_REJECT(context); return KRB5KDC_ERR_CLIENT_NAME_MISMATCH; } @@ -1490,8 +1491,7 @@ pkinit_eku_authorize(krb5_context context, krb5_certauth_moddata moddata, return ret; if (!valid_eku) { - pkiDebug("%s: did not find an acceptable EKU in user certificate\n", - __FUNCTION__); + TRACE_PKINIT_SERVER_EKU_REJECT(context); return KRB5KDC_ERR_INCONSISTENT_KEY_PURPOSE; } @@ -1617,7 +1617,7 @@ pkinit_server_plugin_init(krb5_context context, return ENOMEM; for (i = 0, j = 0; i < numrealms; i++) { - pkiDebug("%s: processing realm '%s'\n", __FUNCTION__, realmnames[i]); + TRACE_PKINIT_SERVER_INIT_REALM(context, realmnames[i]); retval = pkinit_server_plugin_init_realm(context, realmnames[i], &plgctx); if (retval == 0 && plgctx != NULL) realm_contexts[j++] = plgctx; diff --git a/src/plugins/preauth/pkinit/pkinit_trace.h b/src/plugins/preauth/pkinit/pkinit_trace.h index 458d0961e..6abe28c0c 100644 --- a/src/plugins/preauth/pkinit/pkinit_trace.h +++ b/src/plugins/preauth/pkinit/pkinit_trace.h @@ -52,7 +52,7 @@ #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) \ +#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") @@ -91,6 +91,72 @@ #define TRACE_PKINIT_OPENSSL_ERROR(c, msg) \ TRACE(c, "PKINIT OpenSSL error: {str}", msg) +#define TRACE_PKINIT_SERVER_CERT_AUTH(c, modname) \ + TRACE(c, "PKINIT server authorizing cert with module {str}", \ + modname) +#define TRACE_PKINIT_SERVER_EKU_REJECT(c) \ + TRACE(c, "PKINIT server found no acceptable EKU in client cert") +#define TRACE_PKINIT_SERVER_EKU_SKIP(c) \ + TRACE(c, "PKINIT server skipping EKU check due to configuration") +#define TRACE_PKINIT_SERVER_INIT_REALM(c, realm) \ + TRACE(c, "PKINIT server initializing realm {str}", realm) +#define TRACE_PKINIT_SERVER_MATCHING_UPN_FOUND(c) \ + TRACE(c, "PKINIT server found a matching UPN SAN in client cert") +#define TRACE_PKINIT_SERVER_MATCHING_SAN_FOUND(c) \ + TRACE(c, "PKINIT server found a matching SAN in client cert") +#define TRACE_PKINIT_SERVER_NO_SAN(c) \ + TRACE(c, "PKINIT server found no SAN in client cert") +#define TRACE_PKINIT_SERVER_PADATA_VERIFY(c) \ + TRACE(c, "PKINIT server verifying KRB5_PADATA_PK_AS_REQ") +#define TRACE_PKINIT_SERVER_PADATA_VERIFY_OLD(c) \ + TRACE(c, "PKINIT server verifying KRB5_PADATA_PK_AS_REQ_OLD") +#define TRACE_PKINIT_SERVER_PADATA_VERIFY_FAIL(c) \ + TRACE(c, "PKINIT server failed to verify PA data") +#define TRACE_PKINIT_SERVER_RETURN_PADATA(c) \ + TRACE(c, "PKINIT server returning PA data") +#define TRACE_PKINIT_SERVER_SAN_REJECT(c) \ + TRACE(c, "PKINIT server found no acceptable SAN in client cert") + +#define TRACE_PKINIT_EKU(c) \ + TRACE(c, "PKINIT found acceptable EKU and digitalSignature KU") +#define TRACE_PKINIT_EKU_NO_KU(c) \ + TRACE(c, "PKINIT found acceptable EKU but no digitalSignature KU") +#define TRACE_PKINIT_LOADED_CERT(c, name) \ + TRACE(c, "PKINIT loaded cert and key for {str}", name) +#define TRACE_PKINIT_LOAD_FROM_FILE(c) \ + TRACE(c, "PKINIT loading CA certs and CRLs from FILE") +#define TRACE_PKINIT_LOAD_FROM_DIR(c) \ + TRACE(c, "PKINIT loading CA certs and CRLs from DIR") +#define TRACE_PKINIT_NO_CA_ANCHOR(c, file) \ + TRACE(c, "PKINIT no anchor CA in file {str}", file) +#define TRACE_PKINIT_NO_CA_INTERMEDIATE(c, file) \ + TRACE(c, "PKINIT no intermediate CA in file {str}", file) +#define TRACE_PKINIT_NO_CERT(c) \ + TRACE(c, "PKINIT no certificate provided") +#define TRACE_PKINIT_NO_CERT_AND_KEY(c, dirname) \ + TRACE(c, "PKINIT no cert and key pair found in directory {str}", \ + dirname) +#define TRACE_PKINIT_NO_CRL(c, file) \ + TRACE(c, "PKINIT no CRL in file {str}", file) +#define TRACE_PKINIT_NO_DEFAULT_CERT(c, count) \ + TRACE(c, "PKINIT error: There are {int} certs, but there must " \ + "be exactly one.", count) +#define TRACE_PKINIT_NO_MATCHING_CERT(c) \ + TRACE(c, "PKINIT no matching certificate found") +#define TRACE_PKINIT_NO_PRIVKEY(c) \ + TRACE(c, "PKINIT no private key provided") +#define TRACE_PKINIT_PKCS_DECODE_FAIL(c, name) \ + TRACE(c, "PKINIT failed to decode PKCS12 file {str} contents", name) +#define TRACE_PKINIT_PKCS_OPEN_FAIL(c, name, err) \ + TRACE(c, "PKINIT failed to open PKCS12 file {str}: err {errno}", \ + name, err) +#define TRACE_PKINIT_PKCS_PARSE_FAIL_FIRST(c) \ + TRACE(c, "PKINIT initial PKCS12_parse with no password failed") +#define TRACE_PKINIT_PKCS_PARSE_FAIL_SECOND(c) \ + TRACE(c, "PKINIT second PKCS12_parse with password failed") +#define TRACE_PKINIT_PKCS_PROMPT_FAIL(c) \ + TRACE(c, "PKINIT failed to prompt for PKCS12 password") + #define TRACE_CERTAUTH_VTINIT_FAIL(c, ret) \ TRACE(c, "certauth module failed to init vtable: {kerr}", ret) #define TRACE_CERTAUTH_INIT_FAIL(c, name, ret) \