path: root/Convert-some-pkiDebug-messages-to-TRACE-macros.patch

From 4dcab7d706331b469678f3a516cd67fffd331058 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)
---
 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 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)                          \