From b4c2212ae7412e21f4965acdb8c10e4a60b65b9b Mon Sep 17 00:00:00 2001
From: Matt Rogers <mrogers@redhat.com>
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 90c30dbf5..70e230ec2 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) \