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")

Reply via email to