This is an automated email from the ASF dual-hosted git repository. lserris pushed a commit to branch master in repository https://gitbox.apache.org/repos/asf/trafficserver.git
The following commit(s) were added to refs/heads/master by this push: new 4a011db42 Verbose SSL error logs (#9225) 4a011db42 is described below commit 4a011db42a96ddd16a3c011c17bf0de607e4c230 Author: Serris Lew <serrisn...@gmail.com> AuthorDate: Wed Dec 7 09:03:09 2022 -0800 Verbose SSL error logs (#9225) * Verbose SSL error logs * Update log wording * Additional logging Co-authored-by: Serris Lew <lser...@apple.com> --- iocore/net/SSLClientUtils.cc | 13 +++-- iocore/net/SSLConfig.cc | 12 ++--- iocore/net/SSLSecret.cc | 4 +- iocore/net/SSLUtils.cc | 122 +++++++++++++++++++++++++++---------------- 4 files changed, 97 insertions(+), 54 deletions(-) diff --git a/iocore/net/SSLClientUtils.cc b/iocore/net/SSLClientUtils.cc index 5975584a5..ceb9a8cb7 100644 --- a/iocore/net/SSLClientUtils.cc +++ b/iocore/net/SSLClientUtils.cc @@ -268,7 +268,8 @@ SSLCreateClientContext(const struct SSLConfigParams *params, const char *ca_bund } if (!SSL_CTX_use_certificate_chain_file(ctx.get(), cert_path)) { - SSLError("SSLCreateClientContext(): failed to load client certificate."); + SSLError("SSLCreateClientContext(): failed to load client certificate: %s", + (!cert_path || cert_path[0] == '\0') ? "[empty file name]" : cert_path); return nullptr; } @@ -277,17 +278,23 @@ SSLCreateClientContext(const struct SSLConfigParams *params, const char *ca_bund } if (!SSL_CTX_use_PrivateKey_file(ctx.get(), key_path, SSL_FILETYPE_PEM)) { - SSLError("SSLCreateClientContext(): failed to load client private key."); + SSLError("SSLCreateClientContext(): failed to load client private key: %s", + (!key_path || key_path[0] == '\0') ? "[empty file]" : key_path); return nullptr; } if (!SSL_CTX_check_private_key(ctx.get())) { - SSLError("SSLCreateClientContext(): client private key does not match client certificate."); + SSLError("SSLCreateClientContext(): client private key: %s does not match client certificate: %s", + (!key_path || key_path[0] == '\0') ? "[empty file]" : key_path, + (!cert_path || cert_path[0] == '\0') ? "[empty file]" : cert_path); return nullptr; } if (ca_bundle_file || ca_bundle_path) { if (!SSL_CTX_load_verify_locations(ctx.get(), ca_bundle_file, ca_bundle_path)) { + SSLError("SSLCreateClientContext(): Invalid CA Certificate file: %s or CA Certificate path: %s", + (!ca_bundle_file || ca_bundle_file[0] == '\0') ? "[empty file name]" : ca_bundle_file, + (!ca_bundle_path || ca_bundle_path[0] == '\0') ? "[empty path]" : ca_bundle_path); SSLError("SSLCreateClientContext(): Invalid client CA cert file/CA path."); return nullptr; } diff --git a/iocore/net/SSLConfig.cc b/iocore/net/SSLConfig.cc index 6d34998d3..67615eef6 100644 --- a/iocore/net/SSLConfig.cc +++ b/iocore/net/SSLConfig.cc @@ -496,7 +496,7 @@ SSLConfig::startup() void SSLConfig::reconfigure() { - Debug("ssl", "Reload SSLConfig"); + Debug("ssl_load", "Reload SSLConfig"); SSLConfigParams *params; params = new SSLConfigParams; // start loading the next config @@ -555,7 +555,7 @@ SSLCertificateConfig::reconfigure() // twice the healthcheck period to simulate a loading a large certificate set. if (is_action_tag_set("test.multicert.delay")) { const int secs = 60; - Debug("ssl", "delaying certificate reload by %d secs", secs); + Debug("ssl_load", "delaying certificate reload by %d secs", secs); ink_hrtime_sleep(HRTIME_SECONDS(secs)); } @@ -631,7 +631,7 @@ SSLTicketParams::LoadTicket(bool &nochange) struct stat sdata; if (last_load_time && (stat(ticket_key_filename, &sdata) >= 0)) { if (sdata.st_mtime && sdata.st_mtime <= last_load_time) { - Debug("ssl", "ticket key %s has not changed", ticket_key_filename); + Debug("ssl_load", "ticket key %s has not changed", ticket_key_filename); // No updates since last load return true; } @@ -653,7 +653,7 @@ SSLTicketParams::LoadTicket(bool &nochange) default_global_keyblock = keyblock; load_time = time(nullptr); - Debug("ssl", "ticket key reloaded from %s", ticket_key_filename); + Debug("ssl_load", "ticket key reloaded from %s", ticket_key_filename); #endif return true; } @@ -746,7 +746,7 @@ void SSLConfigParams::updateCTX(const std::string &cert_secret_name) const { // Clear the corresponding client CTXs. They will be lazy loaded later - Debug("ssl", "Update cert %s", cert_secret_name.c_str()); + Debug("ssl_load", "Update cert %s", cert_secret_name.c_str()); this->clearCTX(cert_secret_name); // Update the server cert @@ -762,7 +762,7 @@ SSLConfigParams::clearCTX(const std::string &client_cert) const auto ctx_iter = ctx_map_iter->second.find(client_cert); if (ctx_iter != ctx_map_iter->second.end()) { ctx_iter->second = nullptr; - Debug("ssl", "Clear client cert %s %s", ctx_map_iter->first.c_str(), ctx_iter->first.c_str()); + Debug("ssl_load", "Clear client cert %s %s", ctx_map_iter->first.c_str(), ctx_iter->first.c_str()); } } ink_mutex_release(&ctxMapLock); diff --git a/iocore/net/SSLSecret.cc b/iocore/net/SSLSecret.cc index 6cc10150b..b8b01895b 100644 --- a/iocore/net/SSLSecret.cc +++ b/iocore/net/SSLSecret.cc @@ -55,12 +55,14 @@ SSLSecret::loadFile(const std::string &name, std::string &data_item) struct stat statdata; // Load the secret and add it to the map if (stat(name.c_str(), &statdata) < 0) { + Debug("ssl_secret", "File: %s received error: %s", name.c_str(), strerror(errno)); return false; } std::error_code error; data_item = ts::file::load(ts::file::path(name), error); if (error) { // Loading file failed + Debug("ssl_secret", "Loading file: %s failed ", name.c_str()); return false; } if (SSLConfigParams::load_ssl_file_cb) { @@ -116,7 +118,7 @@ SSLSecret::getSecret(const std::string &name, std::string_view &data) const bool SSLSecret::getOrLoadSecret(const std::string &name1, const std::string &name2, std::string_view &data1, std::string_view &data2) { - Debug("ssl_secret", "lookup up secrets for %s and %s", name1.c_str(), name2.c_str()); + Debug("ssl_secret", "lookup up secrets for %s and %s", name1.c_str(), name2.empty() ? "[empty]" : name2.c_str()); std::scoped_lock lock(secret_map_mutex); bool found_secret1 = this->getSecret(name1, data1); bool found_secret2 = name2.empty() || this->getSecret(name2, data2); diff --git a/iocore/net/SSLUtils.cc b/iocore/net/SSLUtils.cc index 22f170ce8..e8a6d1330 100644 --- a/iocore/net/SSLUtils.cc +++ b/iocore/net/SSLUtils.cc @@ -135,7 +135,7 @@ SSL_locking_callback(int mode, int type, const char *file, int line) } else if (mode & CRYPTO_UNLOCK) { ink_mutex_release(&mutex_buf[type]); } else { - Debug("ssl", "invalid SSL locking mode 0x%x", mode); + Debug("ssl_load", "invalid SSL locking mode 0x%x", mode); ink_assert(0); } } @@ -281,11 +281,11 @@ set_context_cert(SSL *ssl, void *arg) goto done; } - Debug("ssl", "set_context_cert ssl=%p server=%s handshake_complete=%d", ssl, servername, netvc->getSSLHandShakeComplete()); + Debug("ssl_load", "set_context_cert ssl=%p server=%s handshake_complete=%d", ssl, servername, netvc->getSSLHandShakeComplete()); // catch the client renegotiation early on if (SSLConfigParams::ssl_allow_client_renegotiation == false && netvc->getSSLHandShakeComplete()) { - Debug("ssl", "set_context_cert trying to renegotiate from the client"); + Debug("ssl_load", "set_context_cert trying to renegotiate from the client"); retval = 0; // Error goto done; } @@ -362,7 +362,8 @@ set_context_cert(SSL *ssl, void *arg) verify_ctx = SSL_get_SSL_CTX(ssl); // set_context_cert found SSL context for ... - Debug("ssl", "ssl_cert_callback %s SSL context %p for requested name '%s'", found ? "found" : "using", verify_ctx, servername); + Debug("ssl_load", "ssl_cert_callback %s SSL context %p for requested name '%s'", found ? "found" : "using", verify_ctx, + servername); if (verify_ctx == nullptr) { retval = 0; @@ -821,7 +822,7 @@ ssl_private_key_passphrase_callback_exec(char *buf, int size, int rwflag, void * *buf = 0; passphrase_cb_userdata *ud = static_cast<passphrase_cb_userdata *>(userdata); - Debug("ssl", "ssl_private_key_passphrase_callback_exec rwflag=%d serverDialog=%s", rwflag, ud->_serverDialog); + Debug("ssl_load", "ssl_private_key_passphrase_callback_exec rwflag=%d serverDialog=%s", rwflag, ud->_serverDialog); // only respond to reading private keys, not writing them (does ats even do that?) if (0 == rwflag) { @@ -855,7 +856,7 @@ ssl_private_key_passphrase_callback_builtin(char *buf, int size, int rwflag, voi *buf = 0; passphrase_cb_userdata *ud = static_cast<passphrase_cb_userdata *>(userdata); - Debug("ssl", "ssl_private_key_passphrase_callback rwflag=%d serverDialog=%s", rwflag, ud->_serverDialog); + Debug("ssl_load", "ssl_private_key_passphrase_callback rwflag=%d serverDialog=%s", rwflag, ud->_serverDialog); // only respond to reading private keys, not writing them (does ats even do that?) if (0 == rwflag) { @@ -987,7 +988,7 @@ SSLInitializeLibrary() // After POST we don't have to lock for FIPS int mode = FIPS_mode(); FIPS_mode_set(mode); - Debug("ssl", "FIPS_mode: %d", mode); + Debug("ssl_load", "FIPS_mode: %d", mode); #endif mutex_buf = static_cast<ink_mutex *>(OPENSSL_malloc(CRYPTO_num_locks() * sizeof(ink_mutex))); @@ -1039,7 +1040,7 @@ SSLPrivateKeyHandler(SSL_CTX *ctx, const SSLConfigParams *params, const char *ke pkey = ENGINE_load_private_key(e, keyPath, nullptr, nullptr); if (pkey) { if (!SSL_CTX_use_PrivateKey(ctx, pkey)) { - SSLError("failed to load server private key from engine"); + Debug("ssl_load", "failed to load server private key from engine"); EVP_PKEY_free(pkey); return false; } @@ -1052,16 +1053,18 @@ SSLPrivateKeyHandler(SSL_CTX *ctx, const SSLConfigParams *params, const char *ke scoped_BIO bio(BIO_new_mem_buf(secret_data, secret_data_len)); pkey = PEM_read_bio_PrivateKey(bio.get(), nullptr, nullptr, nullptr); if (nullptr == pkey) { - SSLError("failed to load server private key from %s", keyPath); + Debug("ssl_load", "failed to load server private key from %s", + (!keyPath || keyPath[0] == '\0') ? "[empty key path]" : keyPath); return false; } if (!SSL_CTX_use_PrivateKey(ctx, pkey)) { - SSLError("failed to attache server private key loaded from %s", keyPath); + Debug("ssl_load", "failed to attach server private key loaded from %s", + (!keyPath || keyPath[0] == '\0') ? "[empty key path]" : keyPath); EVP_PKEY_free(pkey); return false; } if (e == nullptr && !SSL_CTX_check_private_key(ctx)) { - SSLError("server private key does not match the certificate public key"); + Debug("ssl_load", "server private key does not match the certificate public key"); return false; } } @@ -1115,7 +1118,7 @@ SSLMultiCertConfigLoader::check_server_cert_now(X509 *cert, const char *certname return -5; } - Debug("ssl", "server certificate %s passed accessibility and date checks", certname); + Debug("ssl_load", "server certificate %s passed accessibility and date checks", certname); return 0; // all good } /* CheckServerCertNow() */ @@ -1136,7 +1139,7 @@ asn1_strdup(ASN1_STRING *s) static void ssl_callback_info(const SSL *ssl, int where, int ret) { - Debug("ssl", "ssl_callback_info ssl: %p, where: %d, ret: %d, State: %s", ssl, where, ret, SSL_state_string_long(ssl)); + Debug("ssl_load", "ssl_callback_info ssl: %p, where: %d, ret: %d, State: %s", ssl, where, ret, SSL_state_string_long(ssl)); SSLNetVConnection *netvc = SSLNetVCAccess(ssl); @@ -1168,12 +1171,12 @@ ssl_callback_info(const SSL *ssl, int where, int ret) #ifdef TLS1_3_VERSION // TLSv1.3 has no renegotiation. if (SSL_version(ssl) >= TLS1_3_VERSION) { - Debug("ssl", "TLSv1.3 has no renegotiation."); + Debug("ssl_load", "TLSv1.3 has no renegotiation."); return; } #endif netvc->setSSLClientRenegotiationAbort(true); - Debug("ssl", "ssl_callback_info trying to renegotiate from the client"); + Debug("ssl_load", "ssl_callback_info trying to renegotiate from the client"); } } if (where & SSL_CB_HANDSHAKE_DONE) { @@ -1253,7 +1256,7 @@ setClientCertLevel(SSL *ssl, uint8_t certLevel) ink_release_assert(!"Invalid client verify level"); } - Debug("ssl", "setting cert level to %d", server_verify_client); + Debug("ssl_load", "setting cert level to %d", server_verify_client); SSL_set_verify(ssl, server_verify_client, ssl_verify_client_callback); SSL_set_verify_depth(ssl, params->verify_depth); // might want to make configurable at some point. } @@ -1328,7 +1331,8 @@ SSLMultiCertConfigLoader::init_server_ssl_ctx(CertLoadData const &data, const SS ctx_type = (!generate_default_ctx && i < data.cert_type_list.size()) ? data.cert_type_list[i] : SSLCertContextType::GENERIC; - Debug("ssl", "Creating new context %p cert_count=%ld initial: %s", ctx, cert_names_list.size(), cert_names_list[0].c_str()); + Debug("ssl_load", "Creating new context %p cert_count=%ld initial: %s", ctx, cert_names_list.size(), + cert_names_list[0].c_str()); // disable selected protocols SSL_CTX_set_options(ctx, _params->ssl_ctx_options); @@ -1338,7 +1342,7 @@ SSLMultiCertConfigLoader::init_server_ssl_ctx(CertLoadData const &data, const SS } #ifdef SSL_MODE_RELEASE_BUFFERS - Debug("ssl", "enabling SSL_MODE_RELEASE_BUFFERS"); + Debug("ssl_load", "enabling SSL_MODE_RELEASE_BUFFERS"); SSL_CTX_set_mode(ctx, SSL_MODE_RELEASE_BUFFERS); #endif @@ -1534,7 +1538,10 @@ SSLMultiCertConfigLoader::_set_verify_path(SSL_CTX *ctx, const SSLMultiCertConfi if (!sslMultCertSettings->ca && params->serverCACertPath != nullptr) { if ((!SSL_CTX_load_verify_locations(ctx, params->serverCACertFilename, params->serverCACertPath)) || (!SSL_CTX_set_default_verify_paths(ctx))) { - SSLError("invalid CA Certificate file or CA Certificate path"); + SSLError("invalid CA Certificate file: %s or CA Certificate path: %s", + (!params->serverCACertFilename || params->serverCACertFilename[0] == '\0') ? "[empty file name]" : + params->serverCACertFilename, + (!params->serverCACertPath || params->serverCACertPath[0] == '\0') ? "[empty path]" : params->serverCACertPath); return false; } } @@ -1548,13 +1555,13 @@ SSLMultiCertConfigLoader::_setup_session_ticket(SSL_CTX *ctx, const SSLMultiCert // Session tickets are enabled by default. Disable if explicitly requested. if (sslMultCertSettings->session_ticket_enabled == 0) { SSL_CTX_set_options(ctx, SSL_OP_NO_TICKET); - Debug("ssl", "ssl session ticket is disabled"); + Debug("ssl_load", "ssl session ticket is disabled"); } #endif #if defined(TLS1_3_VERSION) && !defined(LIBRESSL_VERSION_NUMBER) && !defined(OPENSSL_IS_BORINGSSL) if (!(this->_params->ssl_ctx_options & SSL_OP_NO_TLSv1_3)) { SSL_CTX_set_num_tickets(ctx, sslMultCertSettings->session_ticket_number); - Debug("ssl", "ssl session ticket number set to %d", sslMultCertSettings->session_ticket_number); + Debug("ssl_load", "ssl session ticket number set to %d", sslMultCertSettings->session_ticket_number); } #endif return true; @@ -1570,7 +1577,10 @@ SSLMultiCertConfigLoader::_setup_client_cert_verification(SSL_CTX *ctx) if (params->serverCACertFilename != nullptr && params->serverCACertPath != nullptr) { if ((!SSL_CTX_load_verify_locations(ctx, params->serverCACertFilename, params->serverCACertPath)) || (!SSL_CTX_set_default_verify_paths(ctx))) { - SSLError("CA Certificate file or CA Certificate path invalid"); + SSLError("invalid CA Certificate file: %s or CA Certificate path: %s", + (!params->serverCACertFilename || params->serverCACertFilename[0] == '\0') ? "[empty file name]" : + params->serverCACertFilename, + (!params->serverCACertPath || params->serverCACertPath[0] == '\0') ? "[empty path]" : params->serverCACertPath); return false; } } @@ -1690,17 +1700,21 @@ SSLCreateServerContext(const SSLConfigParams *params, const SSLMultiCertConfigPa if (ctx && cert_path) { if (!SSL_CTX_use_certificate_file(ctx.get(), cert_path, SSL_FILETYPE_PEM)) { - SSLError("SSLCreateServerContext(): failed to load server certificate."); + SSLError("SSLCreateServerContext(): failed to load server certificate file: %s", + (!cert_path || cert_path[0] == '\0') ? "[empty file]" : cert_path); ctx = nullptr; } else if (!key_path || key_path[0] == '\0') { key_path = cert_path; } if (ctx) { if (!SSL_CTX_use_PrivateKey_file(ctx.get(), key_path, SSL_FILETYPE_PEM)) { - SSLError("SSLCreateServerContext(): failed to load server private key."); + SSLError("SSLCreateServerContext(): failed to load server private key: %s", + (!key_path || key_path[0] == '\0') ? "[empty file]" : key_path); ctx = nullptr; } else if (!SSL_CTX_check_private_key(ctx.get())) { - SSLError("SSLCreateServerContext(): server private key does not match server certificate."); + SSLError("SSLCreateServerContext(): server private key: %s does not match server certificate: %s", + (!key_path || key_path[0] == '\0') ? "[empty file]" : key_path, + (!cert_path || cert_path[0] == '\0') ? "[empty file]" : cert_path); ctx = nullptr; } } @@ -1897,7 +1911,7 @@ SSLMultiCertConfigLoader::_store_single_ssl_ctx(SSLCertLookup *lookup, const sha // Index this certificate by the specified IP(v6) address. If the address is "*", make it the default context. if (sslMultCertSettings->addr) { if (strcmp(sslMultCertSettings->addr, "*") == 0) { - Debug("ssl", "Addr is '*'; setting %p to default", ctx.get()); + Debug("ssl_load", "Addr is '*'; setting %p to default", ctx.get()); if (lookup->insert(sslMultCertSettings->addr, SSLCertContext(ctx, ctx_type, sslMultCertSettings, keyblock)) >= 0) { inserted = true; lookup->ssl_default = ctx; @@ -1952,6 +1966,7 @@ ssl_extract_certificate(const matcher_line *line_info, SSLMultiCertConfigParams if (label == nullptr) { continue; } + Debug("ssl_load", "Extracting certificate label: %s, value: %s", label, value); if (strcasecmp(label, SSL_IP_TAG) == 0) { sslMultCertSettings->addr = ats_strdup(value); @@ -2058,7 +2073,7 @@ SSLMultiCertConfigLoader::load(SSLCertLookup *lookup) const char *errPtr; errPtr = parseConfigLine(line, &line_info, &sslCertTags); - Debug("ssl", "currently parsing %s", line); + Debug("ssl_load", "currently parsing %s at line %d from config file: %s", line, line_num, params->configFilePath); if (errPtr != nullptr) { RecSignalWarning(REC_SIGNAL_CONFIG_ERROR, "%s: discarding %s entry at line %d: %s", __func__, params->configFilePath, line_num, errPtr); @@ -2222,8 +2237,10 @@ SSLMultiCertConfigLoader::load_certs_and_cross_reference_names( key_tok.setString(""); } - if (sslMultCertSettings && sslMultCertSettings->key && cert_tok.getNumTokensRemaining() != key_tok.getNumTokensRemaining()) { - Error("the number of certificates in ssl_cert_name and ssl_key_name doesn't match"); + size_t cert_tok_num = cert_tok.getNumTokensRemaining(); + if (sslMultCertSettings && sslMultCertSettings->key && cert_tok_num != key_tok.getNumTokensRemaining()) { + Error("the number of certificates in ssl_cert_name (%zu) and ssl_key_name (%zu) do not match", cert_tok_num, + key_tok.getNumTokensRemaining()); return false; } @@ -2231,7 +2248,8 @@ SSLMultiCertConfigLoader::load_certs_and_cross_reference_names( if (sslMultCertSettings && sslMultCertSettings->ca) { ca_tok.setString(sslMultCertSettings->ca); if (cert_tok.getNumTokensRemaining() != ca_tok.getNumTokensRemaining()) { - Error("the number of certificates in ssl_cert_name and ssl_ca_name doesn't match"); + Error("the number of certificates in ssl_cert_name (%zu) and ssl_ca_name (%zu) do not match", cert_tok_num, + ca_tok.getNumTokensRemaining()); return false; } } @@ -2240,7 +2258,8 @@ SSLMultiCertConfigLoader::load_certs_and_cross_reference_names( if (sslMultCertSettings && sslMultCertSettings->ocsp_response) { ocsp_tok.setString(sslMultCertSettings->ocsp_response); if (cert_tok.getNumTokensRemaining() != ocsp_tok.getNumTokensRemaining()) { - Error("the number of certificates in ssl_cert_name and ssl_ocsp_name doesn't match"); + Error("the number of certificates in ssl_cert_name (%zu) and ssl_ocsp_name (%zu) do not match", cert_tok_num, + ocsp_tok.getNumTokensRemaining()); return false; } } @@ -2271,16 +2290,21 @@ SSLMultiCertConfigLoader::load_certs_and_cross_reference_names( params->secrets.getOrLoadSecret(data.cert_names_list[i], data.key_list.size() > i ? data.key_list[i] : "", secret_data, secret_key_data); if (secret_data.empty()) { - SSLError("failed to load certificate secret for %s", data.cert_names_list[i].c_str()); + SSLError("failed to load certificate secret for %s with key path %s", data.cert_names_list[i].c_str(), + data.key_list.size() > i ? data.key_list[i].c_str() : "[empty key path]"); return false; } scoped_BIO bio(BIO_new_mem_buf(secret_data.data(), secret_data.size())); X509 *cert = nullptr; if (bio) { cert = PEM_read_bio_X509(bio.get(), nullptr, nullptr, nullptr); + } else { + SSLError("failed to create bio for certificate secret %s of length %ld", data.cert_names_list[i].c_str(), secret_data.size()); + return false; } if (!bio || !cert) { - SSLError("failed to load certificate chain from %s", data.cert_names_list[i].c_str()); + SSLError("failed to load certificate chain from %s of length %ld with key path %s", data.cert_names_list[i].c_str(), + secret_data.size(), data.key_list.size() > i ? data.key_list[i].c_str() : "[empty key path]"); return false; } @@ -2326,9 +2350,12 @@ SSLMultiCertConfigLoader::load_certs_and_cross_reference_names( ASN1_STRING *cn = X509_NAME_ENTRY_get_data(e); subj_name = asn1_strdup(cn); - Debug("ssl", "subj '%s' in certificate %s %p", subj_name.get(), data.cert_names_list[i].c_str(), cert); + Debug("ssl_load", "subj '%s' in certificate %s %p", subj_name.get(), data.cert_names_list[i].c_str(), cert); name_set.insert(subj_name.get()); } + if (name_set.empty()) { + Debug("ssl_load", "no subj name in certificate %s", data.cert_names_list[i].c_str()); + } } // Traverse the subjectAltNames (if any) and insert additional keys for the SSL context. @@ -2341,6 +2368,7 @@ SSLMultiCertConfigLoader::load_certs_and_cross_reference_names( name = sk_GENERAL_NAME_value(names, i); if (name->type == GEN_DNS) { ats_scoped_str dns(asn1_strdup(name->d.dNSName)); + Debug("ssl_load", "inserting dns '%s' in certificate: %s", dns.get(), data.cert_names_list[i].c_str()); name_set.insert(dns.get()); } } @@ -2402,10 +2430,10 @@ SSLMultiCertConfigLoader::load_certs(SSL_CTX *ctx, const std::vector<std::string { #if TS_USE_TLS_OCSP if (SSLConfigParams::ssl_ocsp_enabled) { - Debug("ssl", "SSL OCSP Stapling is enabled"); + Debug("ssl_load", "SSL OCSP Stapling is enabled"); SSL_CTX_set_tlsext_status_cb(ctx, ssl_callback_ocsp_stapling); } else { - Debug("ssl", "SSL OCSP Stapling is disabled"); + Debug("ssl_load", "SSL OCSP Stapling is disabled"); } #else if (SSLConfigParams::ssl_ocsp_enabled) { @@ -2421,13 +2449,17 @@ SSLMultiCertConfigLoader::load_certs(SSL_CTX *ctx, const std::vector<std::string std::string_view secret_key_data; params->secrets.getOrLoadSecret(cert_names_list[i], keyPath, secret_data, secret_key_data); if (secret_data.empty()) { - SSLError("failed to load certificate secret for %s", cert_names_list[i].c_str()); + SSLError("failed to load certificate secret for %s with key path %s", cert_names_list[i].c_str(), + keyPath.empty() ? "[empty key path]" : keyPath.c_str()); return false; } scoped_BIO bio(BIO_new_mem_buf(secret_data.data(), secret_data.size())); X509 *cert = nullptr; if (bio) { cert = PEM_read_bio_X509(bio.get(), nullptr, nullptr, nullptr); + } else { + SSLError("failed to create bio for certificate secret %s of length %ld", data.cert_names_list[i].c_str(), secret_data.size()); + return false; } if (!bio || !cert) { @@ -2435,7 +2467,7 @@ SSLMultiCertConfigLoader::load_certs(SSL_CTX *ctx, const std::vector<std::string return false; } - Debug("ssl", "for ctx=%p, using certificate %s", ctx, cert_names_list[i].c_str()); + Debug("ssl_load", "for ctx=%p, using certificate %s", ctx, cert_names_list[i].c_str()); if (!SSL_CTX_use_certificate(ctx, cert)) { SSLError("Failed to assign cert from %s to SSL_CTX", cert_names_list[i].c_str()); X509_free(cert); @@ -2444,13 +2476,15 @@ SSLMultiCertConfigLoader::load_certs(SSL_CTX *ctx, const std::vector<std::string // Load up any additional chain certificates if (!SSL_CTX_add_extra_chain_cert_bio(ctx, bio.get())) { - Debug("ssl", "couldn't add chain to %p", ctx); + Debug("ssl_load", "couldn't add chain to %p", ctx); } if (secret_key_data.empty()) { secret_key_data = secret_data; } if (!SSLPrivateKeyHandler(ctx, params, keyPath.c_str(), secret_key_data.data(), secret_key_data.size())) { + SSLError("failed to load certificate: %s of length %ld with key path: %s", cert_names_list[i].c_str(), secret_key_data.size(), + keyPath.empty() ? "[empty key path]" : keyPath.c_str()); return false; } // Must load all the intermediate certificates before starting the next chain @@ -2528,9 +2562,9 @@ SSLMultiCertConfigLoader::set_session_id_context(SSL_CTX *ctx, const SSLConfigPa } if (nullptr != setting_cert) { - Debug("ssl", "Using '%s' in hash for session id context", sslMultCertSettings->cert.get()); + Debug("ssl_load", "Using '%s' in hash for session id context", sslMultCertSettings->cert.get()); if (EVP_DigestUpdate(digest, sslMultCertSettings->cert, strlen(setting_cert)) == 0) { - SSLError("EVP_DigestUpdate failed"); + SSLError("EVP_DigestUpdate failed using '%s' in hash for session id context", sslMultCertSettings->cert.get()); goto fail; } } @@ -2542,7 +2576,7 @@ SSLMultiCertConfigLoader::set_session_id_context(SSL_CTX *ctx, const SSLConfigPa X509_NAME *name = sk_X509_NAME_value(ca_list, i); if (X509_NAME_digest(name, evp_md_func, hash_buf /* borrow our final hash buffer. */, &hash_len) == 0 || EVP_DigestUpdate(digest, hash_buf, hash_len) == 0) { - SSLError("Adding X509 name to digest failed"); + SSLError("Adding X509 name to digest failed using '%s' in hash for session id context", hash_buf); goto fail; } } @@ -2552,12 +2586,12 @@ SSLMultiCertConfigLoader::set_session_id_context(SSL_CTX *ctx, const SSLConfigPa } if (EVP_DigestFinal_ex(digest, hash_buf, &hash_len) == 0) { - SSLError("EVP_DigestFinal_ex failed"); + SSLError("EVP_DigestFinal_ex failed using '%s' in hash for session id context", hash_buf); goto fail; } if (SSL_CTX_set_session_id_context(ctx, hash_buf, hash_len) == 0) { - SSLError("SSL_CTX_set_session_id_context failed"); + SSLError("SSL_CTX_set_session_id_context failed using '%s' in hash for session id context", hash_buf); goto fail; }