This is an automated email from the ASF dual-hosted git repository. jpeach 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 cc15797f29 Clean up certifier plugin debug messages. (#9975) cc15797f29 is described below commit cc15797f29d6c98dca6b1903af0c6ff494fd3164 Author: James Peach <jpe...@apache.org> AuthorDate: Fri Aug 11 11:27:06 2023 +1000 Clean up certifier plugin debug messages. (#9975) The certifier plugin manually write out the function name in debug messages, and these were wrong in some cases. Clean this up to use __func__ and a more consistent message format. Remove the "t" mode from fopen call, which is a Windows-ism. Signed-off-by: James Peach <jpe...@apache.org> --- plugins/certifier/certifier.cc | 189 +++++++++++---------- .../pluginTest/certifier/certifier.test.py | 5 +- 2 files changed, 104 insertions(+), 90 deletions(-) diff --git a/plugins/certifier/certifier.cc b/plugins/certifier/certifier.cc index 583df1c754..f73bcb6f39 100644 --- a/plugins/certifier/certifier.cc +++ b/plugins/certifier/certifier.cc @@ -211,7 +211,7 @@ public: // Remove oldest node if size exceeds limit if (++size > limit) { - TSDebug(PLUGIN_NAME, "Removing %s", tail->commonName.c_str()); + TSDebug(PLUGIN_NAME, "%s: removing '%s'", __func__, tail->commonName.c_str()); auto iter = cnDataMap.find(tail->commonName); if (iter != cnDataMap.end()) { local = std::move(iter->second); // copy ownership @@ -224,7 +224,7 @@ public: } } } - TSDebug(PLUGIN_NAME, "%s Prepend to LRU list...List Size:%d Map Size: %d", data->commonName.c_str(), size, + TSDebug(PLUGIN_NAME, "%s: prepending '%s' to LRU ... list size: %d, map size: %d", __func__, data->commonName.c_str(), size, static_cast<int>(cnDataMap.size())); TSMutexUnlock(list_mutex); @@ -344,44 +344,46 @@ addSANExtToCert(X509 *cert, std::string_view dnsName) static scoped_X509 mkcrt(const std::string &commonName, int serial) { - TSDebug(PLUGIN_NAME, "Entering mkcrt()..."); scoped_EVP_PKEY pktmp; scoped_X509 cert; cert.reset(X509_new()); - /// Set X509V3 + // Set X509V3 if (X509_set_version(cert.get(), 2) == 0) { - TSError("[%s] mkcrt(): Failed to set X509V3.", PLUGIN_NAME); + TSError("[%s] %s: failed to set X509V3", PLUGIN_NAME, __func__); return nullptr; } - /// Set serial number + // Set serial number // TSDebug("txn_monitor", "serial: %d", serial); ASN1_INTEGER_set(X509_get_serialNumber(cert.get()), serial); - /// Set issuer from CA cert + // Set issuer from CA cert if (X509_set_issuer_name(cert.get(), X509_get_subject_name(ca_cert_scoped.get())) == 0) { - TSError("[%s] mkcrt(): Failed to set issuer.", PLUGIN_NAME); + TSError("[%s] %s: failed to set certificate issuer", PLUGIN_NAME, __func__); return nullptr; } - /// Set certificate time + + // Set certificate time X509_gmtime_adj(X509_get_notBefore(cert.get()), 0); X509_gmtime_adj(X509_get_notAfter(cert.get()), static_cast<long>(3650) * 24 * 3600); - /// Get handle to subject name + // Get handle to subject name X509_NAME *n = X509_get_subject_name(cert.get()); - /// Set common name field + // Set common name field if (X509_NAME_add_entry_by_txt(n, "CN", MBSTRING_ASC, (unsigned char *)commonName.c_str(), -1, -1, 0) != 1) { - TSError("[%s] mkcsr(): Failed to add entry.", PLUGIN_NAME); + TSError("[%s] %s: failed to add certificate subject CN", PLUGIN_NAME, __func__); return nullptr; } - /// Set Traffic Server public key + + // Set Traffic Server public key if (X509_set_pubkey(cert.get(), ca_pkey_scoped.get()) == 0) { - TSDebug(PLUGIN_NAME, "mkcrt(): Failed to set X509 public key."); + TSError("[%s] %s: failed to set certificate public key", PLUGIN_NAME, __func__); return nullptr; } - /// Add the Subject Alternative Name (SAN) extension + + // Add the Subject Alternative Name (SAN) extension addSANExtToCert(cert.get(), commonName); // Sign the certificate @@ -419,7 +421,7 @@ shadow_cert_generator(TSCont contp, TSEvent event, void *edata) /// Try open the file if directory exists fp = fopen(cert_filename.c_str(), "rt"); } - TSDebug(PLUGIN_NAME, "shadow_cert_generator(): Cert file is expected at %s", cert_filename.c_str()); + TSDebug(PLUGIN_NAME, "%s: cert file is expected at %s", __func__, cert_filename.c_str()); /// If cert file exists and is readable if (fp != nullptr) { cert.reset(PEM_read_X509(fp, nullptr, nullptr, nullptr)); @@ -427,17 +429,16 @@ shadow_cert_generator(TSCont contp, TSEvent event, void *edata) if (cert == nullptr) { /// Problem with cert file / openssl read - TSError("[%s] [shadow_cert_generator] Problem with loading certs", PLUGIN_NAME); - std::remove(cert_filename.c_str()); + TSError("[%s] %s: failed o load certificate from '%s'", PLUGIN_NAME, __func__, cert_filename.c_str()); } else { - TSDebug(PLUGIN_NAME, "shadow_cert_generator(): Loaded cert from file"); + TSDebug(PLUGIN_NAME, "%s: loaded certificate from '%s'", __func__, cert_filename.c_str()); } } /// No valid certs available from disk, create one and write to file if (cert == nullptr) { if (!sign_enabled) { - TSDebug(PLUGIN_NAME, "shadow_cert_generator(): No certs found and dynamic generation disabled. Marked as wontdo."); + TSDebug(PLUGIN_NAME, "%s: no certs found and dynamic generation disabled; marked as wontdo", __func__); // There won't be certs available. Mark this servername as wontdo // Pass on as if plugin doesn't exist ssl_list->setup_data_ctx(commonName, localQ, nullptr, nullptr, true); @@ -450,7 +451,7 @@ shadow_cert_generator(TSCont contp, TSEvent event, void *edata) TSContDestroy(contp); return TS_SUCCESS; } - TSDebug(PLUGIN_NAME, "shadow_cert_generator(): Creating shadow certs"); + TSDebug(PLUGIN_NAME, "%s: creating shadow certs", __func__); /// Get serial number TSMutexLock(serial_mutex); @@ -467,7 +468,7 @@ shadow_cert_generator(TSCont contp, TSEvent event, void *edata) /// Create cert cert = mkcrt(commonName, serial); if (cert == nullptr) { - TSDebug(PLUGIN_NAME, "[shadow_cert_generator] Cert generation failed"); + TSDebug(PLUGIN_NAME, "%s: cert generation failed", __func__); TSContDestroy(contp); ssl_list->set_schedule(commonName, false); return TS_ERROR; @@ -475,10 +476,10 @@ shadow_cert_generator(TSCont contp, TSEvent event, void *edata) /// Write certs to file if ((fp = fopen(cert_filename.c_str(), "w+")) == nullptr) { - TSDebug(PLUGIN_NAME, "shadow_cert_generator(): Error opening file: %s\n", strerror(errno)); + TSDebug(PLUGIN_NAME, "%s: error opening file: %s", __func__, strerror(errno)); } else { if (!PEM_write_X509(fp, cert.get())) { - TSDebug(PLUGIN_NAME, "shadow_cert_generator(): Error writing cert to disk"); + TSDebug(PLUGIN_NAME, "%s: error writing cert to disk", __func__); } fclose(fp); } @@ -489,23 +490,23 @@ shadow_cert_generator(TSCont contp, TSEvent event, void *edata) ctx.reset(ref_ctx); if (SSL_CTX_use_certificate(ref_ctx, cert.get()) < 1) { - TSError("[%s] shadow_cert_handler(): Failed to use certificate in SSL_CTX.", PLUGIN_NAME); + TSError("[%s] %s: failed to use certificate in SSL_CTX", PLUGIN_NAME, __func__); TSContDestroy(contp); ssl_list->set_schedule(commonName, false); return TS_ERROR; } if (SSL_CTX_use_PrivateKey(ref_ctx, ca_pkey_scoped.get()) < 1) { - TSError("[%s] shadow_cert_handler(): Failed to use private key in SSL_CTX.", PLUGIN_NAME); + TSError("[%s] %s: failed to use private key in SSL_CTX", PLUGIN_NAME, __func__); TSContDestroy(contp); ssl_list->set_schedule(commonName, false); return TS_ERROR; } - TSDebug(PLUGIN_NAME, "shadow_cert_generator(): cert and context ready, clearing the queue"); + TSDebug(PLUGIN_NAME, "%s: cert and context ready, clearing the queue", __func__); ssl_list->setup_data_ctx(commonName, localQ, std::move(ctx), std::move(cert), false); /// Clear the queue by setting context for each and reenable them while (!localQ.empty()) { - TSDebug(PLUGIN_NAME, "\tClearing the queue size %lu", localQ.size()); + TSDebug(PLUGIN_NAME, "%s: clearing the queue size %lu", __func__, localQ.size()); TSVConn ssl_vc = reinterpret_cast<TSVConn>(localQ.front()); localQ.pop(); TSSslConnection sslobj = TSVConnSslConnectionGet(ssl_vc); @@ -529,28 +530,33 @@ cert_retriever(TSCont contp, TSEvent event, void *edata) SSL_CTX *ref_ctx = nullptr; if (servername == nullptr) { - TSError("[%s] cert_retriever(): No SNI available.", PLUGIN_NAME); + TSError("[%s] %s: no SNI available", __func__, PLUGIN_NAME); return TS_ERROR; } + bool wontdo = false; ref_ctx = ssl_list->lookup_and_create(servername, edata, wontdo); + if (wontdo) { - TSDebug(PLUGIN_NAME, "cert_retriever(): Won't generate cert for %s", servername); + TSDebug(PLUGIN_NAME, "%s: won't generate cert for %s", __func__, servername); TSVConnReenable(ssl_vc); - } else if (nullptr == ref_ctx) { - // If no existing context, schedule TASK thread to generate - TSDebug(PLUGIN_NAME, "cert_retriever(): schedule thread to generate/retrieve cert for %s", servername); - TSCont schedule_cont = TSContCreate(shadow_cert_generator, TSMutexCreate()); - TSContDataSet(schedule_cont, (void *)servername); - TSContScheduleOnPool(schedule_cont, 0, TS_THREAD_POOL_TASK); - } else { - // Use existing context - TSDebug(PLUGIN_NAME, "cert_retriever(): Reuse existing cert and context for %s", servername); + return TS_SUCCESS; + } + + if (ref_ctx) { + // Use existing context. + TSDebug(PLUGIN_NAME, "%s: reusing existing cert and context for %s", __func__, servername); SSL_set_SSL_CTX(ssl, ref_ctx); TSVConnReenable(ssl_vc); + return TS_SUCCESS; } - /// For scheduled connections, the scheduled continuation will handle the reenabling + // If no existing context, schedule TASK thread to generate. + TSDebug(PLUGIN_NAME, "%s: scheduling thread to generate/retrieve cert for %s", __func__, servername); + TSCont schedule_cont = TSContCreate(shadow_cert_generator, TSMutexCreate()); + TSContDataSet(schedule_cont, const_cast<char *>(servername)); + TSContScheduleOnPool(schedule_cont, 0, TS_THREAD_POOL_TASK); + return TS_SUCCESS; } @@ -607,66 +613,73 @@ TSPluginInit(int argc, const char *argv[]) case '?': break; default: - TSDebug(PLUGIN_NAME, "Unexpected options."); - TSError("[%s] Unexpected options error.", PLUGIN_NAME); + TSDebug(PLUGIN_NAME, "unexpected options"); + TSError("[%s] unexpected options error", PLUGIN_NAME); return; } } // Register plugin and create callback if (TSPluginRegister(&info) != TS_SUCCESS) { - TSError("[%s] Unable to initialize plugin (disabled). Failed to register plugin.", PLUGIN_NAME); - } else if ((cb_shadow = TSContCreate(cert_retriever, nullptr)) == nullptr) { - TSError("[%s] Unable to initialize plugin (disabled). Failed to create shadow cert cb.", PLUGIN_NAME); - } else { - if ((sign_enabled = cert && key && serial)) { - // Dynamic cert generation enabled. Initialize CA key, cert and serial - // To comply to openssl, key and cert file are opened as FILE* - FILE *fp = nullptr; - if ((fp = fopen(cert, "rt")) == nullptr) { - TSDebug(PLUGIN_NAME, "fopen() error is %d: %s for %s", errno, strerror(errno), cert); - TSError("[%s] Unable to initialize plugin. Failed to open ca cert.", PLUGIN_NAME); - return; - } - ca_cert_scoped.reset(PEM_read_X509(fp, nullptr, nullptr, nullptr)); - fclose(fp); + TSError("[%s] unable to initialize plugin (disabled): failed to register plugin", PLUGIN_NAME); + return; + } - if ((fp = fopen(key, "rt")) == nullptr) { - TSDebug(PLUGIN_NAME, "fopen() error is %d: %s for %s", errno, strerror(errno), key); - TSError("[%s] Unable to initialize plugin. Failed to open ca key.", PLUGIN_NAME); - return; - } - ca_pkey_scoped.reset(PEM_read_PrivateKey(fp, nullptr, nullptr, nullptr)); - fclose(fp); + if ((cb_shadow = TSContCreate(cert_retriever, nullptr)) == nullptr) { + TSError("[%s] unable to initialize plugin (disabled): failed to create shadow cert cb", PLUGIN_NAME); + return; + } - if (ca_pkey_scoped == nullptr || ca_cert_scoped == nullptr) { - TSDebug(PLUGIN_NAME, "PEM_read failed to read %s %s", ca_pkey_scoped ? "" : "pkey", ca_cert_scoped ? "" : "cert"); - TSError("[%s] Unable to initialize plugin. Failed to read ca key/cert.", PLUGIN_NAME); - return; - } + if (cert && key && serial) { + sign_enabled = true; - // Read serial file - serial_file.open(serial, std::fstream::in | std::fstream::out); - if (!serial_file.is_open()) { - TSDebug(PLUGIN_NAME, "Failed to open serial file."); - TSError("[%s] Unable to initialize plugin. Failed to open serial.", PLUGIN_NAME); - return; - } - /// Initialize mutex and serial number - serial_mutex = TSMutexCreate(); - ca_serial = 0; - - serial_file.seekg(0, serial_file.beg); - serial_file >> ca_serial; - if (serial_file.bad() || serial_file.fail()) { - ca_serial = 0; - } + // Dynamic cert generation enabled. Initialize CA key, cert and serial + // To comply to openssl, key and cert file are opened as FILE* + FILE *fp = nullptr; + if ((fp = fopen(cert, "r")) == nullptr) { + TSDebug(PLUGIN_NAME, "fopen() error is %d: %s for %s", errno, strerror(errno), cert); + TSError("[%s] unable to initialize plugin: failed to open CA certificate '%s'", PLUGIN_NAME, cert); + return; + } + ca_cert_scoped.reset(PEM_read_X509(fp, nullptr, nullptr, nullptr)); + fclose(fp); + + if ((fp = fopen(key, "r")) == nullptr) { + TSDebug(PLUGIN_NAME, "fopen() error is %d: %s for %s", errno, strerror(errno), key); + TSError("[%s] unable to initialize plugin: failed to open CA key '%s'", PLUGIN_NAME, key); + return; + } + ca_pkey_scoped.reset(PEM_read_PrivateKey(fp, nullptr, nullptr, nullptr)); + fclose(fp); + + if (ca_pkey_scoped == nullptr || ca_cert_scoped == nullptr) { + TSDebug(PLUGIN_NAME, "PEM_read failed to read %s %s", ca_pkey_scoped ? "" : "pkey", ca_cert_scoped ? "" : "cert"); + TSError("[%s] unable to initialize plugin: failed to parse ca key or certificate", PLUGIN_NAME); + return; } - TSDebug(PLUGIN_NAME, "Dynamic cert generation %s", sign_enabled ? "enabled" : "disabled"); - /// Add global hooks - TSHttpHookAdd(TS_SSL_CERT_HOOK, cb_shadow); + // Read serial file + serial_file.open(serial, std::fstream::in | std::fstream::out); + if (!serial_file.is_open()) { + TSDebug(PLUGIN_NAME, "failed to open serial file '%s'", serial); + TSError("[%s] unable to initialize plugin: failed to open serial file '%s'", PLUGIN_NAME, serial); + return; + } + /// Initialize mutex and serial number + serial_mutex = TSMutexCreate(); + ca_serial = 0; + + serial_file.seekg(0, serial_file.beg); + serial_file >> ca_serial; + if (serial_file.bad() || serial_file.fail()) { + ca_serial = 0; + } } + TSDebug(PLUGIN_NAME, "dynamic certificate generation %s", sign_enabled ? "enabled" : "disabled"); + + /// Add global hooks + TSHttpHookAdd(TS_SSL_CERT_HOOK, cb_shadow); + return; } diff --git a/tests/gold_tests/pluginTest/certifier/certifier.test.py b/tests/gold_tests/pluginTest/certifier/certifier.test.py index 202259e889..15f2a0ca2d 100644 --- a/tests/gold_tests/pluginTest/certifier/certifier.test.py +++ b/tests/gold_tests/pluginTest/certifier/certifier.test.py @@ -64,7 +64,7 @@ class DynamicCertTest: f'certifier.so -s {os.path.join(self.certPathDest, "store")} -m 1000 -c {os.path.join(self.certPathDest, "ca.cert")} -k {os.path.join(self.certPathDest, "ca.key")} -r {os.path.join(self.certPathDest, "ca-serial.txt")}') # Verify logs for dynamic generation of certs self.ts.Disk.traffic_out.Content += Testers.ContainsExpression( - "Creating shadow certs", + "creating shadow certs", "Verify the certifier plugin generates the certificate dynamically.") def runHTTPSTraffic(self): @@ -148,7 +148,8 @@ class ReuseExistingCertTest: f'certifier.so -s {os.path.join(self.certPathDest, "store")} -m 1000 -c {os.path.join(self.certPathDest, "ca.cert")} -k {os.path.join(self.certPathDest, "ca.key")} -r {os.path.join(self.certPathDest, "ca-serial.txt")}') # Verify logs for reusing existing cert self.ts.Disk.traffic_out.Content += Testers.ContainsExpression( - "Reuse existing cert and context for www.tls.com", "Should reuse the existing certificate") + "reusing existing cert and context for www.tls.com", + "Should reuse the existing certificate") def runHTTPSTraffic(self): tr = Test.AddTestRun("Test dynamic generation of certs")