AuTest: New log and When condition for ATS initialized

src/traffic_server/traffic_server.cc

@@ -45,6 +45,7 @@
 
 #include <syslog.h>
 #include <algorithm>
+#include <atomic>
 #include <list>
 #include <string>
 
@@ -173,10 +174,10 @@ static int poll_timeout         = -1; // No value set.
 static int cmd_disable_freelist = 0;
 static bool signal_received[NSIG];
 
-// 1: delay listen, wait for cache.
-// 0: Do not delay, start listen ASAP.
+// 1: the main thread delayed accepting, start accepting.
+// 0: delay accept, wait for cache initialization.
 // -1: cache is already initialized, don't delay.
-static int delay_listen_for_cache_p;
+static int delay_listen_for_cache = 0;
 
 AppVersionInfo appVersionInfo; // Build info for this application
 
@@ -452,6 +453,42 @@ class MemoryLimit : public Continuation
   struct rusage _usage;
 };
 
+/** Gate the emission of the "Traffic Server is fuly initialized" log message.
+ *
+ * This message is intended to be helpful to users who want to know that
+ * Traffic Server is not just running but has become fully initialized and is
+ * ready to optimize traffic. This is in contrast to the "traffic server is
+ * running" message which can be printed before either of these conditions.
+ *
+ * This function is called on each initialization state transition. Currently,
+ * the two state transitions of interest are:
+ *
+ * 1. The cache is initialized.
+ * 2. The ports are open and accept has been called upon them.
+ *
+ * Note that Traffic Server configures the port objects and may even open the
+ * ports before calling accept on those ports. The difference between these two
+ * events is communicated to plugins via the
+ * TS_LIFECYCLE_PORTS_INITIALIZED_HOOK and TS_LIFECYCLE_PORTS_READY_HOOK hooks.
+ * If wait_for_cache is enabled, the difference in time between these events
+ * may measure in the tens of milliseconds.  The message emitted by this
+ * function happens after this full lifecycle takes place on these ports and
+ * after cache is initialized.
+ */
+static void
+emit_fully_initialized_message()
+{
+  static std::atomic<unsigned int> initialization_state_counter = 0;
+
+  // See the doxygen comment above explaining what the states are that
+  // constitute Traffic Server being fully initialized.
+  constexpr unsigned int num_initialization_states = 2;
+
+  if (++initialization_state_counter == num_initialization_states) {
+    Note("Traffic Server is fully initialized.");
+  }
+}
+
 void
 set_debug_ip(const char *ip_string)
 {
@@ -709,7 +746,8 @@ CB_After_Cache_Init()
   APIHook *hook;
   int start;
 
-  start = ink_atomic_swap(&delay_listen_for_cache_p, -1);
+  start = ink_atomic_swap(&delay_listen_for_cache, -1);
+  emit_fully_initialized_message();
 
 #if TS_ENABLE_FIPS == 0
   // Check for cache BC after the cache is initialized and before listen, if possible.
@@ -724,8 +762,12 @@ CB_After_Cache_Init()
 #endif
 
   if (1 == start) {
+    // The delay_listen_for_cache value was 1, therefore the main function
+    // delayed the call to start_HttpProxyServer until we got here. We must
+    // call accept on the ports now that the cache is initialized.
     Debug("http_listen", "Delayed listen enable, cache initialization finished");
     start_HttpProxyServer();
+    emit_fully_initialized_message();
   }
 
   time_t cache_ready_at = time(nullptr);
@@ -2091,10 +2133,19 @@ main(int /* argc ATS_UNUSED */, const char **argv)
 
       // Delay only if config value set and flag value is zero
       // (-1 => cache already initialized)
-      if (delay_p && ink_atomic_cas(&delay_listen_for_cache_p, 0, 1)) {
+      if (delay_p && ink_atomic_cas(&delay_listen_for_cache, 0, 1)) {
         Debug("http_listen", "Delaying listen, waiting for cache initialization");
       } else {
+        // If we've come here, either:
+        //
+        // 1. The user did not configure wait_for_cache, and/or
+        // 2. The previous delay_listen_for_cache value was not 0, thus the cache
+        //    must have been initialized already.
+        //
+        // In either case we should not delay to accept the ports.
+        Debug("http_listen", "Not delaying listen");
         start_HttpProxyServer(); // PORTS_READY_HOOK called from in here
+        emit_fully_initialized_message();
       }
     }
     // Plugins can register their own configuration names so now after they've done that

tests/gold_tests/autest-site/traffic_replay.test.ext

@@ -80,7 +80,7 @@ def Replay(obj, name, replay_dir, key=None, cert=None, conn_type='mixed', option
     tr.Setup.MakeDir(data_dir)
     tr.Setup.Copy(replay_dir, data_dir)
     tr.Processes.Default.StartBefore(server)
-    tr.Processes.Default.StartBefore(ts, ready=When.PortOpen(ts.Variables.ssl_port))
+    tr.Processes.Default.StartBefore(ts)
     tr.Processes.Default.StartBefore(dns)
     tr.ReturnCode = Any(None, 0)
     tr.Processes.Default.Streams.All = Testers.ExcludesExpression("FAIL", "No fails allowed.")

tests/gold_tests/autest-site/trafficserver.test.ext

@@ -28,7 +28,8 @@ def make_id(s):
 # this forms is for the global process define
 
 
-def MakeATSProcess(obj, name, command='traffic_server', select_ports=True, enable_tls=False):
+def MakeATSProcess(obj, name, command='traffic_server', select_ports=True,
+                   enable_tls=False, enable_cache=True):
     #####################################
     # common locations
 
@@ -281,10 +282,26 @@ def MakeATSProcess(obj, name, command='traffic_server', select_ports=True, enabl
     get_port(p, "manager_port")
     get_port(p, "admin_port")
 
-    if enable_tls:
-        p.Ready = When.PortsOpen([p.Variables.port, p.Variables.ssl_port])
+    if enable_cache:
+        # In records.config, the cache is enabled by default so there's nothing
+        # we have to do here to functionally enable it. However, the tests that
+        # rely upon the cache will not function correctly if ATS starts
+        # processing traffic before the cache is ready. Thus we set the
+        # wait_for_cache configuration.
+        p.Disk.records_config.update({
+            # Do not accept connections from clients until cache subsystem is
+            # operational.
+            'proxy.config.http.wait_for_cache': 1,
+        })
     else:
-        p.Ready = When.PortOpen(p.Variables.port)
+        # The user wants the cache to be disabled.
+        p.Disk.records_config.update({
+            'proxy.config.http.cache.http': 0
+        })
+
+    # The following message was added so that tests and users can know when
+    # Traffic Server is ready to both receive and optimize traffic.
+    p.Ready = When.FileContains(p.Disk.diags_log.AbsPath, "NOTE: Traffic Server is fully initialized")
 
     if select_ports:
         # default config

tests/gold_tests/autest-site/when.test.ext

@@ -19,18 +19,67 @@ When extensions.
 
 from autest.api import AddWhenFunction
 import hosts.output as host
+import os
+import re
 
 
-def FileContains(haystack, needle):
+def FileContains(haystack, needle, desired_count=1):
+    """
+    Return whether the file haystack contains the string needle.
+
+    Args:
+        haystack (str): The path to the file to be inspected.
+        needle (str): The content to look for in haystack. This can be a
+            regular expression which will be used in Python's re.search
+            function.
+        desired_count (int): How many times the caller desires to see needle in
+            haystack before considering the When condition fulfilled.
+
+    Returns:
+        True if the haystack exists as a file and contains needle, False
+        otherwise.
+    """
+
+    if desired_count < 0:
+        raise ValueError("Cannot pass a negative desired_count value to FileContains.")
+    if desired_count == 0:
+        raise ValueError("Cannot pass a desired_count of 0 to FileContains.")
+
+    if not os.path.exists(haystack):
+        host.WriteDebug(
+            ['FileContains', 'when'],
+            "Testing for file content '{0}' in file '{1}': file does not exist".format(
+                needle, haystack))
+        return False
+
+    needle_regex = re.compile(needle)
     with open(haystack) as f:
-        result = needle in f.read()
+        needle_seen_count = 0
+        line_count = 0
+        for line in f:
+            line_count += 1
+            if needle_regex.search(line):
+                host.WriteDebug(
+                    ['FileContains', 'when'],
+                    "Found '{0}' in file '{1}' in line: '{2}', line number: {3}".format(
+                        needle, haystack, line.rstrip(), line_count))
+                needle_seen_count += 1
+
+                if needle_seen_count >= desired_count:
+                    host.WriteDebug(
+                        ['FileContains', 'when'],
+                        "Testing for file content '{0}' in file '{1}', "
+                        "successfully found it the desired {2} times".format(
+                            needle, haystack, needle_seen_count))
+                    return True
 
         host.WriteDebug(
-            ['FileExists', 'when'],
-            "Testing for file content '{0}' in '{1}' : {2}".format(
-                needle, haystack, result))
+            ['FileContains', 'when'],
+            "Testing for file content '{0}' in file '{1}', only seen {2} "
+            "out of the desired {3} times".format(
+                needle, haystack, needle_seen_count, desired_count))
 
-        return result
+        return False
 
 
 AddWhenFunction(FileContains)

tests/gold_tests/basic/config.test.py

@@ -19,8 +19,10 @@
 Test.Summary = "Test start up of Traffic server with configuration modification of starting port"
 
 ts = Test.MakeATSProcess("ts", select_ports=False)
-ts.Setup.ts.CopyConfig('config/records_8090.config', "records.config")
 ts.Variables.port = 8090
+ts.Disk.records_config.update({
+    'proxy.config.http.server_ports': str(ts.Variables.port),
+})
 ts.Ready = When.PortOpen(ts.Variables.port)
 t = Test.AddTestRun("Test traffic server started properly")
 t.Processes.Default.StartBefore(ts)

tests/gold_tests/basic/copy_config.test.py

@@ -20,13 +20,17 @@
 
 # set up some ATS processes
 ts1 = Test.MakeATSProcess("ts1", select_ports=False)
-ts1.Setup.ts.CopyConfig('config/records_8090.config', 'records.config')
 ts1.Variables.port = 8090
+ts1.Disk.records_config.update({
+    'proxy.config.http.server_ports': str(ts1.Variables.port),
+})
 ts1.Ready = When.PortOpen(ts1.Variables.port)
 
 ts2 = Test.MakeATSProcess("ts2", select_ports=False)
-ts2.Setup.ts.CopyConfig('config/records_8091.config', 'records.config')
 ts2.Variables.port = 8091
+ts2.Disk.records_config.update({
+    'proxy.config.http.server_ports': str(ts2.Variables.port),
+})
 ts2.Ready = When.PortOpen(ts2.Variables.port)
 
 # setup a testrun

tests/gold_tests/basic/copy_config2.test.py

@@ -29,8 +29,8 @@
 p = t.Processes.Default
 p.Command = "curl 127.0.0.1:{0}".format(ts1.Variables.port)
 p.ReturnCode = 0
-p.StartBefore(Test.Processes.ts1, ready=When.PortOpen(ts1.Variables.port))
-p.StartBefore(Test.Processes.ts2, ready=When.PortOpen(ts2.Variables.port))
+p.StartBefore(Test.Processes.ts1)
+p.StartBefore(Test.Processes.ts2)
 
 # setup a testrun
 t = Test.AddTestRun("Talk to ts2")

tests/gold_tests/basic/deny0.test.py

@@ -31,13 +31,12 @@
 dns = Test.MakeDNServer("dns")
 dns.addRecords(records={HOST1: ['127.0.0.1']})
 
-ts = Test.MakeATSProcess("ts")
+ts = Test.MakeATSProcess("ts", enable_cache=False)
 ts.Disk.records_config.update({
      'proxy.config.diags.debug.enabled': 1
     ,'proxy.config.diags.debug.tags': 'http|dns|redirect'
     ,'proxy.config.http.redirection_enabled': 1
     ,'proxy.config.http.number_of_redirections': 1
-    ,'proxy.config.http.cache.http': 0
     ,'proxy.config.dns.nameservers': '127.0.0.1:{0}'.format(dns.Variables.Port)
     ,'proxy.config.dns.resolv_conf': 'NULL'
     ,'proxy.config.url_remap.remap_required': 0  # need this so the domain gets a chance to be evaluated through DNS
@@ -58,7 +57,7 @@ def buildMetaTest(testName, requestString):
   global isFirstTest
   if isFirstTest:
     isFirstTest = False
-    tr.Processes.Default.StartBefore(ts, ready=When.PortOpen(ts.Variables.port))
+    tr.Processes.Default.StartBefore(ts)
     tr.Processes.Default.StartBefore(redirect_serv, ready=When.PortOpen(redirect_serv.Variables.Port))
     tr.Processes.Default.StartBefore(dns)
   with open(os.path.join(data_path, tr.Name), 'w') as f:

tests/gold_tests/bigobj/bigobj.test.py

@@ -35,12 +35,8 @@
 ts.addSSLfile("ssl/server.key")
 
 ts.Disk.records_config.update({
-    # Do not accept connections from clients until cache subsystem is operational.
-    'proxy.config.http.wait_for_cache': 1,
-
     'proxy.config.diags.debug.enabled': 1,
     'proxy.config.diags.debug.tags': 'http|dns|cache',
-    'proxy.config.http.cache.http': 1,  # enable caching.
     'proxy.config.http.cache.required_headers': 0,  # No required headers for caching
     'proxy.config.http.push_method_enabled': 1,
     'proxy.config.proxy_name': 'Poxy_Proxy',  # This will be the server name.
@@ -78,7 +74,7 @@
 
 tr = Test.AddTestRun()
 # Delay on readiness of TS IPv4 ssl port
-tr.Processes.Default.StartBefore(Test.Processes.ts, ready=When.PortOpen(ts.Variables.ssl_port))
+tr.Processes.Default.StartBefore(Test.Processes.ts)
 #
 # Put object with URL http://localhost/bigobj in cache using PUSH request.
 tr.Processes.Default.Command = (