Add -verbosity option to apps/cmp.c and add log output also in crypto/cmp

* In the cmp app so far the -verbosity option had been missing.
* Extend log output helpful for debugging CMP applications
  in setup_ssl_ctx() of the cmp app, ossl_cmp_msg_add_extraCerts(),
  OSSL_CMP_validate_msg(), and OSSL_CMP_MSG_http_perform().
* Correct suppression of log output with insufficient severity.
* Add logging/severity level OSSL_CMP_LOG_TRACE = OSSL_CMP_LOG_MAX.

Reviewed-by: Tomas Mraz <tmraz@fedoraproject.org>
(Merged from https://github.com/openssl/openssl/pull/12739)

4 files changed, 35 insertions, 14 deletions

diff --git a/crypto/cmp/cmp_ctx.c b/crypto/cmp/cmp_ctx.c
index e731f15958..57878a8f8d 100644
--- a/crypto/cmp/cmp_ctx.c
+++ b/crypto/cmp/cmp_ctx.c
@@ -420,6 +420,8 @@ int OSSL_CMP_CTX_set_log_cb(OSSL_CMP_CTX *ctx, OSSL_CMP_log_cb_t cb)
 /* Print OpenSSL and CMP errors via the log cb of the ctx or ERR_print_errors */
 void OSSL_CMP_CTX_print_errors(const OSSL_CMP_CTX *ctx)
 {
+    if (ctx != NULL && OSSL_CMP_LOG_ERR > ctx->log_verbosity)
+        return; /* suppress output since severity is not sufficient */
     OSSL_CMP_print_errors_cb(ctx == NULL ? NULL : ctx->log_cb);
 }
 
@@ -954,7 +956,7 @@ int OSSL_CMP_CTX_set_option(OSSL_CMP_CTX *ctx, int opt, int val)
 
     switch (opt) {
     case OSSL_CMP_OPT_LOG_VERBOSITY:
-        if (val > OSSL_CMP_LOG_DEBUG) {
+        if (val > OSSL_CMP_LOG_MAX) {
             CMPerr(0, CMP_R_VALUE_TOO_LARGE);
             return 0;
         }
diff --git a/crypto/cmp/cmp_http.c b/crypto/cmp/cmp_http.c
index 3804f2498f..f3cd06fb23 100644
--- a/crypto/cmp/cmp_http.c
+++ b/crypto/cmp/cmp_http.c
@@ -40,6 +40,7 @@ OSSL_CMP_MSG *OSSL_CMP_MSG_http_perform(OSSL_CMP_CTX *ctx,
     char server_port[32] = { '\0' };
     STACK_OF(CONF_VALUE) *headers = NULL;
     const char *const content_type_pkix = "application/pkixcmp";
+    int tls_used;
     OSSL_CMP_MSG *res;
 
     if (ctx == NULL || req == NULL) {
@@ -53,16 +54,18 @@ OSSL_CMP_MSG *OSSL_CMP_MSG_http_perform(OSSL_CMP_CTX *ctx,
     if (ctx->serverPort != 0)
         BIO_snprintf(server_port, sizeof(server_port), "%d", ctx->serverPort);
 
+    tls_used = OSSL_CMP_CTX_get_http_cb_arg(ctx) != NULL;
+    ossl_cmp_log2(DEBUG, ctx, "connecting to CMP server %s%s",
+                  ctx->server, tls_used ? " using TLS" : "");
     res = (OSSL_CMP_MSG *)
         OSSL_HTTP_post_asn1(ctx->server, server_port, ctx->serverPath,
-                            OSSL_CMP_CTX_get_http_cb_arg(ctx) != NULL,
-                            ctx->proxy, ctx->no_proxy, NULL, NULL,
+                            tls_used, ctx->proxy, ctx->no_proxy, NULL, NULL,
                             ctx->http_cb, OSSL_CMP_CTX_get_http_cb_arg(ctx),
                             headers, content_type_pkix, (const ASN1_VALUE *)req,
                             ASN1_ITEM_rptr(OSSL_CMP_MSG),
                             0, 0, ctx->msg_timeout, content_type_pkix,
                             ASN1_ITEM_rptr(OSSL_CMP_MSG));
-
+    ossl_cmp_debug(ctx, "disconnected from CMP server");
     sk_CONF_VALUE_pop_free(headers, X509V3_conf_free);
     return res;
 }
diff --git a/crypto/cmp/cmp_protect.c b/crypto/cmp/cmp_protect.c
index 212ef92f50..140b1720c8 100644
--- a/crypto/cmp/cmp_protect.c
+++ b/crypto/cmp/cmp_protect.c
@@ -147,16 +147,24 @@ int ossl_cmp_msg_add_extraCerts(OSSL_CMP_CTX *ctx, OSSL_CMP_MSG *msg)
             return 0;
         /* if we have untrusted certs, try to add intermediate certs */
         if (ctx->untrusted_certs != NULL) {
-            STACK_OF(X509) *chain =
-                ossl_cmp_build_cert_chain(ctx->libctx, ctx->propq,
-                                          ctx->untrusted_certs, ctx->cert);
-            int res = X509_add_certs(msg->extraCerts, chain,
-                                     X509_ADD_FLAG_UP_REF | X509_ADD_FLAG_NO_DUP
-                                     | X509_ADD_FLAG_NO_SS);
-
+            STACK_OF(X509) *chain;
+            int res;
+
+            ossl_cmp_debug(ctx,
+                           "trying to build chain for own CMP signer cert");
+            chain = ossl_cmp_build_cert_chain(ctx->libctx, ctx->propq,
+                                              ctx->untrusted_certs, ctx->cert);
+            res = X509_add_certs(msg->extraCerts, chain,
+                                 X509_ADD_FLAG_UP_REF | X509_ADD_FLAG_NO_DUP
+                                 | X509_ADD_FLAG_NO_SS);
             sk_X509_pop_free(chain, X509_free);
-            if (res == 0)
+            if (res == 0) {
+                ossl_cmp_err(ctx,
+                             "could not build chain for own CMP signer cert");
                 return 0;
+            }
+            ossl_cmp_debug(ctx,
+                           "succeeded building chain for own CMP signer cert");
         }
     }
 
diff --git a/crypto/cmp/cmp_vfy.c b/crypto/cmp/cmp_vfy.c
index b50a3fe83a..86e39d262e 100644
--- a/crypto/cmp/cmp_vfy.c
+++ b/crypto/cmp/cmp_vfy.c
@@ -552,6 +552,7 @@ int OSSL_CMP_validate_msg(OSSL_CMP_CTX *ctx, const OSSL_CMP_MSG *msg)
 {
     X509 *scrt;
 
+    ossl_cmp_debug(ctx, "validating CMP message");
     if (ctx == NULL || msg == NULL
             || msg->header == NULL || msg->body == NULL) {
         CMPerr(0, CMP_R_NULL_ARGUMENT);
@@ -593,8 +594,11 @@ int OSSL_CMP_validate_msg(OSSL_CMP_CTX *ctx, const OSSL_CMP_MSG *msg)
             default:
                 break;
             }
+            ossl_cmp_debug(ctx,
+                           "sucessfully validated PBM-based CMP message protection");
             return 1;
         }
+        ossl_cmp_warn(ctx, "verifying PBM-based CMP message protection failed");
         break;
 
         /*
@@ -615,9 +619,13 @@ int OSSL_CMP_validate_msg(OSSL_CMP_CTX *ctx, const OSSL_CMP_MSG *msg)
                 return 1;
         } else { /* use pinned sender cert */
             /* use ctx->srvCert for signature check even if not acceptable */
-            if (verify_signature(ctx, msg, scrt))
+            if (verify_signature(ctx, msg, scrt)) {
+                ossl_cmp_debug(ctx,
+                               "sucessfully validated signature-based CMP message protection");
+
                 return 1;
-            ossl_cmp_warn(ctx, "msg signature verification failed");
+            }
+            ossl_cmp_warn(ctx, "CMP message signature verification failed");
             CMPerr(0, CMP_R_SRVCERT_DOES_NOT_VALIDATE_MSG);
         }
         break;