diff options
author | Dr. David von Oheimb <David.von.Oheimb@siemens.com> | 2020-08-26 10:11:14 +0200 |
---|---|---|
committer | Dr. David von Oheimb <David.von.Oheimb@siemens.com> | 2020-09-01 18:53:41 +0200 |
commit | 1a5ae1da14f24a170c200c653c8b81e4a2966d3e (patch) | |
tree | f29ce4ca28c2af2c4587a7c566a33dc1346bebf2 | |
parent | 807b0a1dbb65fcf0d432184326e76e9f745dc3f1 (diff) |
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)
-rw-r--r-- | apps/cmp.c | 94 | ||||
-rw-r--r-- | crypto/cmp/cmp_ctx.c | 4 | ||||
-rw-r--r-- | crypto/cmp/cmp_http.c | 9 | ||||
-rw-r--r-- | crypto/cmp/cmp_protect.c | 24 | ||||
-rw-r--r-- | crypto/cmp/cmp_vfy.c | 12 | ||||
-rw-r--r-- | doc/man1/openssl-cmp.pod.in | 8 | ||||
-rw-r--r-- | doc/man3/OSSL_CMP_log_open.pod | 3 | ||||
-rw-r--r-- | include/openssl/cmp_util.h | 2 | ||||
-rw-r--r-- | util/other.syms | 1 |
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 |