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)

9 files changed, 110 insertions, 47 deletions

diff --git a/apps/cmp.c b/apps/cmp.c
index 97fa322b11..4a8b6e75fb 100644
--- a/apps/cmp.c
+++ b/apps/cmp.c
@@ -51,6 +51,7 @@ static char *opt_config = NULL;
 #define SECTION_NAME_MAX 40 /* max length of section name */
 #define DEFAULT_SECTION "default"
 static char *opt_section = CMP_SECTION;
+static int opt_verbosity = OSSL_CMP_LOG_INFO;
 
 #undef PROG
 #define PROG cmp_main
@@ -194,7 +195,7 @@ static X509_VERIFY_PARAM *vpm = NULL;
 
 typedef enum OPTION_choice {
     OPT_ERR = -1, OPT_EOF = 0, OPT_HELP,
-    OPT_CONFIG, OPT_SECTION,
+    OPT_CONFIG, OPT_SECTION, OPT_VERBOSITY,
 
     OPT_CMD, OPT_INFOTYPE, OPT_GENINFO,
 
@@ -257,6 +258,8 @@ const OPTIONS cmp_options[] = {
      "Configuration file to use. \"\" = none. Default from env variable OPENSSL_CONF"},
     {"section", OPT_SECTION, 's',
      "Section(s) in config file to get options from. \"\" = 'default'. Default 'cmp'"},
+    {"verbosity", OPT_VERBOSITY, 'n',
+     "Log level; 3=ERR, 4=WARN, 6=INFO, 7=DEBUG, 8=TRACE. Default 6 = INFO"},
 
     OPT_SECTION("Generic message"),
     {"cmd", OPT_CMD, 's', "CMP request to send: ir/cr/kur/p10cr/rr/genm"},
@@ -507,7 +510,7 @@ typedef union {
     long *num_long;
 } varref;
 static varref cmp_vars[] = { /* must be in same order as enumerated above! */
-    {&opt_config}, {&opt_section},
+    {&opt_config}, {&opt_section}, {(char **)&opt_verbosity},
 
     {&opt_cmd_s}, {&opt_infotype_s}, {&opt_geninfo},
 
@@ -564,28 +567,32 @@ static varref cmp_vars[] = { /* must be in same order as enumerated above! */
     {NULL}
 };
 
-#ifndef NDEBUG
-# define FUNC (strcmp(OPENSSL_FUNC, "(unknown function)") == 0  \
-               ? "CMP" : "OPENSSL_FUNC")
-# define PRINT_LOCATION(bio) BIO_printf(bio, "%s:%s:%d:", \
-                                        FUNC, OPENSSL_FILE, OPENSSL_LINE)
-#else
-# define PRINT_LOCATION(bio) ((void)0)
-#endif
-#define CMP_print(bio, prefix, msg, a1, a2, a3) \
-    (PRINT_LOCATION(bio), \
-     BIO_printf(bio, "CMP %s: " msg "\n", prefix, a1, a2, a3))
-#define CMP_INFO(msg, a1, a2, a3)  CMP_print(bio_out, "info", msg, a1, a2, a3)
+#define FUNC (strcmp(OPENSSL_FUNC, "(unknown function)") == 0   \
+              ? "CMP" : OPENSSL_FUNC)
+#define CMP_print(bio, level, prefix, msg, a1, a2, a3) \
+    ((void)(level > opt_verbosity ? 0 : \
+            (BIO_printf(bio, "%s:%s:%d:CMP %s: " msg "\n", \
+                        FUNC, OPENSSL_FILE, OPENSSL_LINE, prefix, a1, a2, a3))))
+#define CMP_DEBUG(m, a1, a2, a3) \
+    CMP_print(bio_out, OSSL_CMP_LOG_DEBUG, "debug", m, a1, a2, a3)
+#define CMP_debug(msg)             CMP_DEBUG(msg"%s%s%s", "", "", "")
+#define CMP_debug1(msg, a1)        CMP_DEBUG(msg"%s%s",   a1, "", "")
+#define CMP_debug2(msg, a1, a2)    CMP_DEBUG(msg"%s",     a1, a2, "")
+#define CMP_debug3(msg, a1, a2, a3) CMP_DEBUG(msg,        a1, a2, a3)
+#define CMP_INFO(msg, a1, a2, a3) \
+    CMP_print(bio_out, OSSL_CMP_LOG_INFO, "info", msg, a1, a2, a3)
 #define CMP_info(msg)              CMP_INFO(msg"%s%s%s", "", "", "")
 #define CMP_info1(msg, a1)         CMP_INFO(msg"%s%s",   a1, "", "")
 #define CMP_info2(msg, a1, a2)     CMP_INFO(msg"%s",     a1, a2, "")
 #define CMP_info3(msg, a1, a2, a3) CMP_INFO(msg,         a1, a2, a3)
-#define CMP_WARN(m, a1, a2, a3)    CMP_print(bio_out, "warning", m, a1, a2, a3)
+#define CMP_WARN(m, a1, a2, a3) \
+    CMP_print(bio_out, OSSL_CMP_LOG_WARNING, "warning", m, a1, a2, a3)
 #define CMP_warn(msg)              CMP_WARN(msg"%s%s%s", "", "", "")
 #define CMP_warn1(msg, a1)         CMP_WARN(msg"%s%s",   a1, "", "")
 #define CMP_warn2(msg, a1, a2)     CMP_WARN(msg"%s",     a1, a2, "")
 #define CMP_warn3(msg, a1, a2, a3) CMP_WARN(msg,         a1, a2, a3)
-#define CMP_ERR(msg, a1, a2, a3)   CMP_print(bio_err, "error", msg, a1, a2, a3)
+#define CMP_ERR(msg, a1, a2, a3) \
+    CMP_print(bio_err, OSSL_CMP_LOG_ERR, "error", msg, a1, a2, a3)
 #define CMP_err(msg)               CMP_ERR(msg"%s%s%s", "", "", "")
 #define CMP_err1(msg, a1)          CMP_ERR(msg"%s%s",   a1, "", "")
 #define CMP_err2(msg, a1, a2)      CMP_ERR(msg"%s",     a1, a2, "")
@@ -597,6 +604,16 @@ static int print_to_bio_out(const char *func, const char *file, int line,
     return OSSL_CMP_print_to_bio(bio_out, func, file, line, level, msg);
 }
 
+static int set_verbosity(int level)
+{
+    if (level < OSSL_CMP_LOG_EMERG || level > OSSL_CMP_LOG_MAX) {
+        CMP_err1("Logging verbosity level %d out of range (0 .. 8)", level);
+        return 0;
+    }
+    opt_verbosity = level;
+    return 1;
+}
+
 static char *next_item(char *opt) /* in list separated by comma and/or space */
 {
     /* advance to separator (comma or whitespace), if any */
@@ -1476,11 +1493,14 @@ static SSL_CTX *setup_ssl_ctx(OSSL_CMP_CTX *ctx, ENGINE *engine)
                 goto err;
             }
         }
-        if (!SSL_CTX_build_cert_chain(ssl_ctx,
-                                      SSL_BUILD_CHAIN_FLAG_UNTRUSTED |
-                                      SSL_BUILD_CHAIN_FLAG_NO_ROOT)) {
-            CMP_warn("could not build cert chain for own TLS cert");
+        CMP_debug("trying to build cert chain for own TLS cert");
+        if (SSL_CTX_build_cert_chain(ssl_ctx,
+                                     SSL_BUILD_CHAIN_FLAG_UNTRUSTED |
+                                     SSL_BUILD_CHAIN_FLAG_NO_ROOT)) {
+            CMP_debug("succeeded building cert chain for own TLS cert");
+        } else {
             OSSL_CMP_CTX_print_errors(ctx);
+            CMP_warn("could not build cert chain for own TLS cert");
         }
 
         /* If present we append to the list also the certs from opt_tls_extra */
@@ -2224,12 +2244,14 @@ static int read_config(void)
     const OPTIONS *opt;
     int provider_option;
     int verification_option;
-
+    int start = OPT_VERBOSITY;
     /*
-     * starting with offset OPT_SECTION because OPT_CONFIG and OPT_SECTION would
-     * not make sense within the config file. They have already been handled.
+     * starting with offset OPT_VERBOSITY because OPT_CONFIG and OPT_SECTION
+     * would not make sense within the config file.
+     * Moreover, these two options and OPT_VERBOSITY have already been handled.
      */
-    for (i = OPT_SECTION - OPT_HELP, opt = &cmp_options[OPT_SECTION];
+
+    for (i = start - OPT_HELP, opt = &cmp_options[start];
          opt->name; i++, opt++) {
         if (!strcmp(opt->name, OPT_SECTION_STR)
                 || !strcmp(opt->name, OPT_MORE_STR)) {
@@ -2255,11 +2277,6 @@ static int read_config(void)
                 continue; /* option not provided */
             }
             break;
-            /*
-             * do not use '<' in cmp_options. Incorrect treatment
-             * somewhere in args_verify() can wrongly set badarg = 1
-             */
-        case '<':
         case 's':
         case 'M':
             txt = conf_get_string(conf, opt_section, opt->name);
@@ -2368,8 +2385,8 @@ static int get_opts(int argc, char **argv)
             opt_help(cmp_options);
             return -1;
         case OPT_CONFIG: /* has already been handled */
-            break;
         case OPT_SECTION: /* has already been handled */
+        case OPT_VERBOSITY: /* has already been handled */
             break;
         case OPT_SERVER:
             opt_server = opt_str("server");
@@ -2700,15 +2717,20 @@ int cmp_main(int argc, char **argv)
     }
 
     /*
-     * handle OPT_CONFIG and OPT_SECTION upfront to take effect for other opts
+     * handle options -config, -section, and -verbosity upfront
+     * to take effect for other options
      */
     for (i = 1; i < argc - 1; i++) {
         if (*argv[i] == '-') {
             if (!strcmp(argv[i] + 1, cmp_options[OPT_CONFIG - OPT_HELP].name))
-                opt_config = argv[i + 1];
+                opt_config = argv[++i];
             else if (!strcmp(argv[i] + 1,
                              cmp_options[OPT_SECTION - OPT_HELP].name))
-                opt_section = argv[i + 1];
+                opt_section = argv[++i];
+            else if (strcmp(argv[i] + 1,
+                            cmp_options[OPT_VERBOSITY - OPT_HELP].name) == 0
+                     && !set_verbosity(atoi(argv[++i])))
+                goto err;
         }
     }
     if (opt_section[0] == '\0') /* empty string */
@@ -2783,6 +2805,7 @@ int cmp_main(int argc, char **argv)
     cmp_ctx = OSSL_CMP_CTX_new(app_get0_libctx(), app_get0_propq());
     if (cmp_ctx == NULL)
         goto err;
+    OSSL_CMP_CTX_set_log_verbosity(cmp_ctx, opt_verbosity);
     if (!OSSL_CMP_CTX_set_log_cb(cmp_ctx, print_to_bio_out)) {
         CMP_err1("cannot set up error reporting and logging for %s", prog);
         goto err;
@@ -2943,6 +2966,11 @@ int cmp_main(int argc, char **argv)
                                                OSSL_CMP_PKISI_BUFLEN);
 
             CMP_print(bio_err,
+                      status == OSSL_CMP_PKISTATUS_accepted
+                      ? OSSL_CMP_LOG_INFO :
+                      status == OSSL_CMP_PKISTATUS_rejection
+                      || status == OSSL_CMP_PKISTATUS_waiting
+                      ? OSSL_CMP_LOG_ERR : OSSL_CMP_LOG_WARNING,
                       status == OSSL_CMP_PKISTATUS_accepted ? "info" :
                       status == OSSL_CMP_PKISTATUS_rejection ? "server error" :
                       status == OSSL_CMP_PKISTATUS_waiting ? "internal error"
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;
diff --git a/doc/man1/openssl-cmp.pod.in b/doc/man1/openssl-cmp.pod.in
index a6a769af9d..77d38d9d75 100644
--- a/doc/man1/openssl-cmp.pod.in
+++ b/doc/man1/openssl-cmp.pod.in
@@ -81,6 +81,7 @@ B<openssl> B<cmp>
 [B<-tls_trusted> I<filenames>]
 [B<-tls_host> I<name>]
 
+[B<-verbosity> I<level>]
 [B<-batch>]
 [B<-repeat> I<number>]
 [B<-reqin>] I<filenames>
@@ -770,6 +771,13 @@ If not given it defaults to the B<-server> address.
 
 =over 4
 
+=item B<-verbosity> I<level>
+
+Level of verbosity for logging, error output, etc.
+0 = EMERG, 1 = ALERT, 2 = CRIT, 3 = ERR, 4 = WARN, 5 = NOTE,
+6 = INFO, 7 = DEBUG, 8 = TRACE.
+Defaults to 6 = INFO.
+
 =item B<-batch>
 
 Do not interactively prompt for input, for instance when a password is needed.
diff --git a/doc/man3/OSSL_CMP_log_open.pod b/doc/man3/OSSL_CMP_log_open.pod
index fdc416c0cf..5c6b924bda 100644
--- a/doc/man3/OSSL_CMP_log_open.pod
+++ b/doc/man3/OSSL_CMP_log_open.pod
@@ -13,6 +13,8 @@ OSSL_CMP_LOG_WARNING,
 OSSL_CMP_LOG_NOTICE,
 OSSL_CMP_LOG_INFO,
 OSSL_CMP_LOG_DEBUG,
+OSSL_CMP_LOG_TRACE,
+
 OSSL_CMP_log_cb_t,
 OSSL_CMP_print_to_bio,
 OSSL_CMP_print_errors_cb
@@ -35,6 +37,7 @@ OSSL_CMP_print_errors_cb
  #define OSSL_CMP_LOG_NOTICE  5
  #define OSSL_CMP_LOG_INFO    6
  #define OSSL_CMP_LOG_DEBUG   7
+ #define OSSL_CMP_LOG_TRACE   8
 
  typedef int (*OSSL_CMP_log_cb_t)(const char *component,
                                   const char *file, int line,
diff --git a/include/openssl/cmp_util.h b/include/openssl/cmp_util.h
index a243d7e742..becbc9208e 100644
--- a/include/openssl/cmp_util.h
+++ b/include/openssl/cmp_util.h
@@ -38,6 +38,8 @@ typedef int OSSL_CMP_severity;
 #  define OSSL_CMP_LOG_NOTICE  5
 #  define OSSL_CMP_LOG_INFO    6
 #  define OSSL_CMP_LOG_DEBUG   7
+#  define OSSL_CMP_LOG_TRACE   8
+#  define OSSL_CMP_LOG_MAX     OSSL_CMP_LOG_TRACE
 typedef int (*OSSL_CMP_log_cb_t)(const char *func, const char *file, int line,
                                  OSSL_CMP_severity level, const char *msg);
 
diff --git a/util/other.syms b/util/other.syms
index 964e09f0bd..6dcc9b260c 100644
--- a/util/other.syms
+++ b/util/other.syms
@@ -388,6 +388,7 @@ OSSL_CMP_LOG_EMERG                      define
 OSSL_CMP_LOG_ERR                        define
 OSSL_CMP_LOG_INFO                       define
 OSSL_CMP_LOG_NOTICE                     define
+OSSL_CMP_LOG_TRACE                      define
 OSSL_CMP_LOG_WARNING                    define
 OSSL_CMP_MSTR_HELPER                    define
 OSSL_CMP_MSTR                           define