You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@trafficserver.apache.org by rr...@apache.org on 2019/02/20 00:24:32 UTC

[trafficserver] branch master updated: Adds logging around various config file loads

This is an automated email from the ASF dual-hosted git repository.

rrm 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 9f5396e  Adds logging around various config file loads
9f5396e is described below

commit 9f5396ee87c48e645ffc712f18de1d32849341dd
Author: Randall Meyer <ra...@yahoo.com>
AuthorDate: Mon Jun 4 10:09:41 2018 -0700

    Adds logging around various config file loads
    
    Also changes the messaging of all config file loads to be consistent
    
    Addresses issue #1348
---
 iocore/cache/CacheHosting.cc                 | 11 +++++++++++
 iocore/cache/Store.cc                        |  6 ++++++
 iocore/dns/SplitDNS.cc                       |  5 +++++
 iocore/net/SSLConfig.cc                      |  4 ++--
 iocore/net/SSLSNIConfig.cc                   |  8 ++++----
 iocore/net/SSLUtils.cc                       |  2 +-
 lib/records/P_RecCore.cc                     |  2 +-
 proxy/CacheControl.cc                        |  6 +++++-
 proxy/IPAllow.cc                             |  4 +++-
 proxy/ParentSelection.cc                     |  8 ++++++++
 proxy/Plugin.cc                              |  8 +++++++-
 proxy/ReverseProxy.cc                        | 11 +++++++----
 proxy/logging/LogConfig.cc                   |  6 +++---
 tests/gold_tests/tls/tls_client_cert.test.py |  2 +-
 tests/gold_tests/tls/tls_tunnel.test.py      |  6 +++---
 15 files changed, 67 insertions(+), 22 deletions(-)

diff --git a/iocore/cache/CacheHosting.cc b/iocore/cache/CacheHosting.cc
index 08573d7..a57d3bb 100644
--- a/iocore/cache/CacheHosting.cc
+++ b/iocore/cache/CacheHosting.cc
@@ -244,6 +244,8 @@ int fstat_wrapper(int fd, struct stat *s);
 int
 CacheHostTable::BuildTableFromString(const char *config_file_path, char *file_buf)
 {
+  Note("hosting.config loading ...");
+
   // Table build locals
   Tokenizer bufTok("\n");
   tok_iter_state i_state;
@@ -323,6 +325,7 @@ CacheHostTable::BuildTableFromString(const char *config_file_path, char *file_bu
     if (gen_host_rec.Init(type)) {
       Warning("Problems encountered while initializing the Generic Volume");
     }
+    Note("hosting.config finished loading");
     return 0;
   }
 
@@ -370,6 +373,8 @@ CacheHostTable::BuildTableFromString(const char *config_file_path, char *file_bu
     last    = current;
     current = current->next;
     ats_free(last);
+
+    Note("hosting.config finished loading");
   }
 
   if (!generic_rec_initd) {
@@ -591,14 +596,20 @@ ConfigVolumes::read_config_file()
   config_path = RecConfigReadConfigPath("proxy.config.cache.volume_filename");
   ink_release_assert(config_path);
 
+  Note("volume.config loading ...");
+
   file_buf = readIntoBuffer(config_path, "[CacheVolition]", nullptr);
   if (file_buf == nullptr) {
+    Error("volume.config failed to load");
     Warning("Cannot read the config file: %s", (const char *)config_path);
     return;
   }
 
   BuildListFromString(config_path, file_buf);
   ats_free(file_buf);
+
+  Note("volume.config finished loading");
+
   return;
 }
 
diff --git a/iocore/cache/Store.cc b/iocore/cache/Store.cc
index d302816..bcafbd4 100644
--- a/iocore/cache/Store.cc
+++ b/iocore/cache/Store.cc
@@ -327,9 +327,11 @@ Store::read_config()
   ats_scoped_fd fd;
   ats_scoped_str storage_path(RecConfigReadConfigPath("proxy.config.cache.storage_filename", "storage.config"));
 
+  Note("storage.config loading ...");
   Debug("cache_init", "Store::read_config, fd = -1, \"%s\"", (const char *)storage_path);
   fd = ::open(storage_path, O_RDONLY);
   if (fd < 0) {
+    Error("storage.config failed to load");
     return Result::failure("open %s: %s", (const char *)storage_path, strerror(errno));
   }
 
@@ -369,6 +371,7 @@ Store::read_config()
       if (ParseRules::is_digit(*e)) {
         if ((size = ink_atoi64(e)) <= 0) {
           delete sd;
+          Error("storage.config failed to load");
           return Result::failure("failed to parse size '%s'", e);
         }
       } else if (0 == strncasecmp(HASH_BASE_STRING_KEY, e, sizeof(HASH_BASE_STRING_KEY) - 1)) {
@@ -386,6 +389,7 @@ Store::read_config()
         }
         if (!*e || !ParseRules::is_digit(*e) || 0 >= (volume_num = ink_atoi(e))) {
           delete sd;
+          Error("storage.config failed to load");
           return Result::failure("failed to parse volume number '%s'", e);
         }
       }
@@ -437,6 +441,8 @@ Store::read_config()
   sd = nullptr; // these are all used.
   sort();
 
+  Note("storage.config finished loading");
+
   return Result::ok();
 }
 
diff --git a/iocore/dns/SplitDNS.cc b/iocore/dns/SplitDNS.cc
index 9834a8b..998ef74 100644
--- a/iocore/dns/SplitDNS.cc
+++ b/iocore/dns/SplitDNS.cc
@@ -132,12 +132,15 @@ SplitDNSConfig::reconfigure()
     return;
   }
 
+  Note("splitdns.config loading ...");
+
   SplitDNS *params = new SplitDNS;
 
   params->m_SplitDNSlEnable = gsplit_dns_enabled;
   params->m_DNSSrvrTable    = new DNS_table("proxy.config.dns.splitdns.filename", modulePrefix, &sdns_dest_tags);
 
   if (nullptr == params->m_DNSSrvrTable || (0 == params->m_DNSSrvrTable->getEntryCount())) {
+    Error("splitdns.config failed to load");
     Warning("No NAMEDs provided! Disabling SplitDNS");
     gsplit_dns_enabled = 0;
     delete params;
@@ -157,6 +160,8 @@ SplitDNSConfig::reconfigure()
   if (is_debug_tag_set("splitdns_config")) {
     SplitDNSConfig::print();
   }
+
+  Note("splitdns.config finished loading");
 }
 
 /* --------------------------------------------------------------
diff --git a/iocore/net/SSLConfig.cc b/iocore/net/SSLConfig.cc
index 71d79fb..2d67244 100644
--- a/iocore/net/SSLConfig.cc
+++ b/iocore/net/SSLConfig.cc
@@ -534,9 +534,9 @@ SSLCertificateConfig::reconfigure()
   }
 
   if (retStatus) {
-    Note("ssl_multicert.config done reloading!");
+    Note("ssl_multicert.config finished loading");
   } else {
-    Note("failed to reload ssl_multicert.config");
+    Error("ssl_multicert.config failed to load");
   }
 
   return retStatus;
diff --git a/iocore/net/SSLSNIConfig.cc b/iocore/net/SSLSNIConfig.cc
index 1925374..006f56a 100644
--- a/iocore/net/SSLSNIConfig.cc
+++ b/iocore/net/SSLSNIConfig.cc
@@ -124,11 +124,11 @@ SNIConfigParams::Initialize()
 {
   sni_filename = ats_stringdup(RecConfigReadConfigPath("proxy.config.ssl.servername.filename"));
 
-  Note("loading %s", sni_filename);
+  Note("ssl_server_name.yaml loading ...");
 
   struct stat sbuf;
   if (stat(sni_filename, &sbuf) == -1 && errno == ENOENT) {
-    Note("failed to reload ssl_server_name.yaml");
+    Note("ssl_server_name.yaml failed to load");
     Warning("Loading SNI configuration - filename: %s doesn't exist", sni_filename);
     return 1;
   }
@@ -137,12 +137,12 @@ SNIConfigParams::Initialize()
   if (!zret.isOK()) {
     std::stringstream errMsg;
     errMsg << zret;
-    Error("failed to load ssl_server_name.yaml: %s", errMsg.str().c_str());
+    Error("ssl_server_name.yaml failed to load: %s", errMsg.str().c_str());
     return 1;
   }
 
   loadSNIConfig();
-  Note("ssl_server_name.yaml done reloading!");
+  Note("ssl_server_name.yaml finished loading");
 
   return 0;
 }
diff --git a/iocore/net/SSLUtils.cc b/iocore/net/SSLUtils.cc
index cf87bd4..53255b1 100644
--- a/iocore/net/SSLUtils.cc
+++ b/iocore/net/SSLUtils.cc
@@ -2212,7 +2212,7 @@ SSLParseCertificateConfiguration(const SSLConfigParams *params, SSLCertLookup *l
 
   const matcher_tags sslCertTags = {nullptr, nullptr, nullptr, nullptr, nullptr, nullptr, false};
 
-  Note("loading SSL certificate configuration from %s", params->configFilePath);
+  Note("ssl_multicert.config loading ...");
 
   if (params->configFilePath) {
     file_buf = readIntoBuffer(params->configFilePath, __func__, nullptr);
diff --git a/lib/records/P_RecCore.cc b/lib/records/P_RecCore.cc
index 1da0cc9..e89ccb9 100644
--- a/lib/records/P_RecCore.cc
+++ b/lib/records/P_RecCore.cc
@@ -641,7 +641,7 @@ RecReadConfigFile(bool inc_version)
   // lock our hash table
   ink_rwlock_wrlock(&g_records_rwlock);
 
-  // Parse the actual fileand hash the values.
+  // Parse the actual file and hash the values.
   RecConfigFileParse(g_rec_config_fpath, RecConsumeConfigEntry, inc_version);
 
   // release our hash table
diff --git a/proxy/CacheControl.cc b/proxy/CacheControl.cc
index 5d5da5e..6e78ed0 100644
--- a/proxy/CacheControl.cc
+++ b/proxy/CacheControl.cc
@@ -144,17 +144,21 @@ initCacheControl()
 //
 //  Called when the cache.conf file changes.  Since it called
 //   infrequently, we do the load of new file as blocking I/O and
-//   lock aquire is also blocking
+//   lock acquire is also blocking
 //
 void
 reloadCacheControl()
 {
+  Note("cache.config loading ...");
+
   CC_table *newTable;
 
   Debug("cache_control", "cache.config updated, reloading");
   eventProcessor.schedule_in(new CC_FreerContinuation(CacheControlTable), CACHE_CONTROL_TIMEOUT, ET_CACHE);
   newTable = new CC_table("proxy.config.cache.control.filename", modulePrefix, &http_dest_tags);
   ink_atomic_swap(&CacheControlTable, newTable);
+
+  Note("cache.config finished loading");
 }
 
 void
diff --git a/proxy/IPAllow.cc b/proxy/IPAllow.cc
index ed208d9..3419258 100644
--- a/proxy/IPAllow.cc
+++ b/proxy/IPAllow.cc
@@ -77,12 +77,14 @@ IpAllow::reconfigure()
 {
   self_type *new_table;
 
-  Note("ip_allow.config updated, reloading");
+  Note("ip_allow.config loading ...");
 
   new_table = new self_type("proxy.config.cache.ip_allow.filename");
   new_table->BuildTable();
 
   configid = configProcessor.set(configid, new_table);
+
+  Note("ip_allow.config finished loading");
 }
 
 IpAllow *
diff --git a/proxy/ParentSelection.cc b/proxy/ParentSelection.cc
index af463f9..6e7e963 100644
--- a/proxy/ParentSelection.cc
+++ b/proxy/ParentSelection.cc
@@ -279,6 +279,8 @@ ParentConfig::startup()
 void
 ParentConfig::reconfigure()
 {
+  Note("parent.config loading ...");
+
   ParentConfigParams *params = nullptr;
 
   // Allocate parent table
@@ -292,6 +294,8 @@ ParentConfig::reconfigure()
   if (is_debug_tag_set("parent_config")) {
     ParentConfig::print();
   }
+
+  Note("parent.config finished loading");
 }
 
 // void ParentConfig::print
@@ -895,6 +899,8 @@ setup_socks_servers(ParentRecord *rec_arr, int len)
 void
 SocksServerConfig::reconfigure()
 {
+  Note("socks.config loading ...");
+
   char *default_val = nullptr;
   int retry_time    = 30;
   int fail_threshold;
@@ -936,6 +942,8 @@ SocksServerConfig::reconfigure()
   if (is_debug_tag_set("parent_config")) {
     SocksServerConfig::print();
   }
+
+  Note("socks.config finished loading");
 }
 
 void
diff --git a/proxy/Plugin.cc b/proxy/Plugin.cc
index 174c6d0..e6b43e5 100644
--- a/proxy/Plugin.cc
+++ b/proxy/Plugin.cc
@@ -234,10 +234,11 @@ plugin_init(bool validateOnly)
     INIT_ONCE  = false;
   }
 
+  Note("plugin.config loading ...");
   path = RecConfigReadConfigPath(nullptr, "plugin.config");
   fd   = open(path, O_RDONLY);
   if (fd < 0) {
-    Warning("unable to open plugin config file '%s': %d, %s", (const char *)path, errno, strerror(errno));
+    Warning("plugin.config failed to load: %d, %s", errno, strerror(errno));
     return false;
   }
 
@@ -312,5 +313,10 @@ plugin_init(bool validateOnly)
   }
 
   close(fd);
+  if (retVal) {
+    Note("plugin.config finished loading");
+  } else {
+    Error("plugin.config failed to load");
+  }
   return retVal;
 }
diff --git a/proxy/ReverseProxy.cc b/proxy/ReverseProxy.cc
index 99c7677..8fe9da8 100644
--- a/proxy/ReverseProxy.cc
+++ b/proxy/ReverseProxy.cc
@@ -64,9 +64,11 @@ init_reverse_proxy()
   reconfig_mutex = new_ProxyMutex();
   rewrite_table  = new UrlRewrite();
 
+  Note("remap.config loading ...");
   if (!rewrite_table->is_valid()) {
-    Fatal("unable to load remap.config");
+    Fatal("remap.config failed to load");
   }
+  Note("remap.config finished loading");
 
   REC_RegisterConfigUpdateFunc("proxy.config.url_remap.filename", url_rewrite_CB, (void *)FILE_CHANGED);
   REC_RegisterConfigUpdateFunc("proxy.config.proxy_name", url_rewrite_CB, (void *)TSNAME_CHANGED);
@@ -134,10 +136,11 @@ reloadUrlRewrite()
 {
   UrlRewrite *newTable, *oldTable;
 
+  Note("remap.config loading ...");
   Debug("url_rewrite", "remap.config updated, reloading...");
   newTable = new UrlRewrite();
   if (newTable->is_valid()) {
-    static const char *msg = "remap.config done reloading!";
+    static const char *msg = "remap.config finished loading";
 
     // Hold at least one lease, until we reload the configuration
     newTable->acquire();
@@ -154,11 +157,11 @@ reloadUrlRewrite()
     Note("%s", msg);
     return true;
   } else {
-    static const char *msg = "failed to reload remap.config, not replacing!";
+    static const char *msg = "remap.config failed to load";
 
     delete newTable;
     Debug("url_rewrite", "%s", msg);
-    Warning("%s", msg);
+    Error("%s", msg);
     return false;
   }
 }
diff --git a/proxy/logging/LogConfig.cc b/proxy/logging/LogConfig.cc
index 757c0bb..4b09754 100644
--- a/proxy/logging/LogConfig.cc
+++ b/proxy/logging/LogConfig.cc
@@ -972,14 +972,14 @@ LogConfig::evaluate_config()
     return false;
   }
 
-  Note("loading logging.yaml");
+  Note("logging.yaml loading ...");
   YamlLogConfig y(this);
 
   bool zret = y.parse(path.get());
   if (zret) {
-    Note("logging.yaml done reloading!");
+    Note("logging.yaml finished loading");
   } else {
-    Note("failed to reload logging.yaml");
+    Note("logging.yaml failed to load");
   }
 
   return zret;
diff --git a/tests/gold_tests/tls/tls_client_cert.test.py b/tests/gold_tests/tls/tls_client_cert.test.py
index 58bb03e..6c6bcc8 100644
--- a/tests/gold_tests/tls/tls_client_cert.test.py
+++ b/tests/gold_tests/tls/tls_client_cert.test.py
@@ -178,7 +178,7 @@ tr2.Processes.Default.ReturnCode = 0
 # At that point the new ssl_server_name settings are ready to go
 def ssl_server_name_reload_done(tsenv):
   def done_reload(process, hasRunFor, **kw):
-    cmd = "grep 'ssl_server_name.yaml done reloading!' {0} | wc -l > {1}/test.out".format(ts.Disk.diags_log.Name, Test.RunDirectory)
+    cmd = "grep 'ssl_server_name.yaml finished loading' {0} | wc -l > {1}/test.out".format(ts.Disk.diags_log.Name, Test.RunDirectory)
     retval = subprocess.run(cmd, shell=True, env=tsenv)
     if retval.returncode == 0:
       cmd ="if [ -f {0}/test.out -a \"`cat {0}/test.out`\" = \"2\" ] ; then true; else false; fi".format(Test.RunDirectory)
diff --git a/tests/gold_tests/tls/tls_tunnel.test.py b/tests/gold_tests/tls/tls_tunnel.test.py
index 5f653db..36dc012 100644
--- a/tests/gold_tests/tls/tls_tunnel.test.py
+++ b/tests/gold_tests/tls/tls_tunnel.test.py
@@ -33,7 +33,7 @@ server_foo = Test.MakeOriginServer("server_foo", ssl=True)
 server_bar = Test.MakeOriginServer("server_bar", ssl=True)
 server2 = Test.MakeOriginServer("server2")
 
-request_foo_header = {"headers": "GET / HTTP/1.1\r\nHost: foo.com\r\n\r\n", "timestamp": "1469733493.993", "body": ""} 
+request_foo_header = {"headers": "GET / HTTP/1.1\r\nHost: foo.com\r\n\r\n", "timestamp": "1469733493.993", "body": ""}
 request_bar_header = {"headers": "GET / HTTP/1.1\r\nHost: bar.com\r\n\r\n", "timestamp": "1469733493.993", "body": ""}
 response_foo_header = {"headers": "HTTP/1.1 200 OK\r\nConnection: close\r\n\r\n", "timestamp": "1469733493.993", "body": "foo ok"}
 response_bar_header = {"headers": "HTTP/1.1 200 OK\r\nConnection: close\r\n\r\n", "timestamp": "1469733493.993", "body": "bar ok"}
@@ -75,7 +75,7 @@ ts.Disk.records_config.update({
 })
 
 # foo.com should not terminate.  Just tunnel to server_foo
-# bar.com should terminate.  
+# bar.com should terminate.
 # empty SNI should tunnel to server_bar
 ts.Disk.ssl_server_name_yaml.AddLines([
   '- fqdn: foo.com',
@@ -160,7 +160,7 @@ trreload.Processes.Default.ReturnCode = 0
 # At that point the new ssl_server_name settings are ready to go
 def ssl_server_name_reload_done(tsenv):
   def done_reload(process, hasRunFor, **kw):
-    cmd = "grep 'ssl_server_name.yaml done reloading!' {0} | wc -l > {1}/test.out".format(ts.Disk.diags_log.Name, Test.RunDirectory)
+    cmd = "grep 'ssl_server_name.yaml finished loading' {0} | wc -l > {1}/test.out".format(ts.Disk.diags_log.Name, Test.RunDirectory)
     retval = subprocess.run(cmd, shell=True, env=tsenv)
     if retval.returncode == 0:
       cmd ="if [ -f {0}/test.out -a \"`cat {0}/test.out`\" = \"2\" ] ; then true; else false; fi".format(Test.RunDirectory)