krb5 commit: Convert some pkiDebug messages to TRACE macros

https://github.com/krb5/krb5/commit/9852862a83952a94300adfafa3e333f43396ec33
commit 9852862a83952a94300adfafa3e333f43396ec33
Author: Matt Rogers <[email protected]>
Date:   Wed Mar 29 10:35:13 2017 -0400

    Convert some pkiDebug messages to TRACE macros
    
    ticket: 8568 (new)

 src/plugins/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 d8c80c1..8bd8aa5 100644
--- a/src/plugins/preauth/pkinit/pkinit_crypto_openssl.c
+++ b/src/plugins/preauth/pkinit/pkinit_crypto_openssl.c
@@ -2308,7 +2308,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) {
@@ -2342,7 +2341,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);
@@ -2351,12 +2349,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);
         }
@@ -4298,8 +4294,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);
@@ -4307,8 +4302,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;
     }
     /*
@@ -4326,7 +4320,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. */
@@ -4367,14 +4361,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;
         }
     }
@@ -4497,8 +4491,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;
     }
 
@@ -4526,8 +4519,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;
     }
 
@@ -4571,8 +4563,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
@@ -4580,8 +4571,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;
     }
@@ -5280,9 +5270,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;
     }
@@ -5430,7 +5418,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 {
@@ -5440,7 +5428,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 {
@@ -5450,7 +5438,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 {
@@ -5536,14 +5524,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 5de2812..c161a71 100644
--- a/src/plugins/preauth/pkinit/pkinit_identity.c
+++ b/src/plugins/preauth/pkinit/pkinit_identity.c
@@ -597,7 +597,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;
@@ -610,8 +609,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 aa80f18..c1ce84b 100644
--- a/src/plugins/preauth/pkinit/pkinit_matching.c
+++ b/src/plugins/preauth/pkinit/pkinit_matching.c
@@ -707,6 +707,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 91c56d6..24da789 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) {
@@ -1455,8 +1457,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;
     }
 
@@ -1482,8 +1483,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;
     }
 
@@ -1664,7 +1664,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 56821f1..acd485b 100644
--- a/src/plugins/preauth/pkinit/pkinit_trace.h
+++ b/src/plugins/preauth/pkinit/pkinit_trace.h
@@ -54,7 +54,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")
@@ -93,6 +93,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)                          \