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)

Signed-off-by: Robbie Harwood <rharwood@redhat.com>

---

 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)                          \