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>
 
@@ -174,10 +175,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
 
@@ -453,6 +454,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)
 {
@@ -710,7 +747,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.
@@ -725,8 +763,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);
@@ -2092,10 +2134,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

@@ -83,7 +83,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
 
@@ -279,10 +280,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")
 
     # set the ports
     if select_ports:

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,10 +31,10 @@
 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({
     # need this so the domain gets a chance to be evaluated through DNS
-    '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
+    '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.dns.nameservers': '127.0.0.1:{0}'.format(dns.Variables.Port), 'proxy.config.dns.resolv_conf': 'NULL', 'proxy.config.url_remap.remap_required': 0
 })
 
 Test.Setup.Copy(os.path.join(Test.Variables.AtsTestToolsDir, 'tcp_client.py'))
@@ -54,7 +54,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/cache/cache-control.test.py

@@ -60,8 +60,6 @@
     'proxy.config.diags.debug.enabled': 1,
     'proxy.config.diags.debug.tags': 'http',
     'proxy.config.http.response_via_str': 3,
-    'proxy.config.http.cache.http': 1,
-    'proxy.config.http.wait_for_cache': 1,
     'proxy.config.http.insert_age_in_response': 0,
 })
 
@@ -72,7 +70,7 @@
 # Test 1 - 200 response and cache fill
 tr = Test.AddTestRun()
 tr.Processes.Default.StartBefore(server)
-tr.Processes.Default.StartBefore(Test.Processes.ts, ready=1)
+tr.Processes.Default.StartBefore(Test.Processes.ts)
 tr.Processes.Default.Command = 'curl -s -D - -v --ipv4 --http1.1 -H "x-debug: x-cache,via" -H "Host: www.example.com" http://localhost:{port}/max_age_10sec'.format(
     port=ts.Variables.port)
 tr.Processes.Default.ReturnCode = 0

tests/gold_tests/cache/cache-generation-clear.test.py

@@ -50,8 +50,7 @@
 tr.Processes.Default.Command = 'curl "http://127.0.0.1:{0}/default/cache/10/{1}" -H "x-debug: x-cache,x-cache-key,via,x-cache-generation" --verbose'.format(
     ts.Variables.port, objectid)
 tr.Processes.Default.ReturnCode = 0
-# time delay as proxy.config.http.wait_for_cache could be broken
-tr.Processes.Default.StartBefore(Test.Processes.ts, ready=5)
+tr.Processes.Default.StartBefore(Test.Processes.ts)
 tr.Processes.Default.Streams.All = "gold/miss_default-1.gold"
 
 # Second touch is a HIT for default.

tests/gold_tests/cache/cache-generation-disjoint.test.py

@@ -30,7 +30,6 @@
 ts.Disk.records_config.update({
     'proxy.config.body_factory.enable_customizations': 3,  # enable domain specific body factory
     'proxy.config.http.cache.generation': -1,  # Start with cache turned off
-    'proxy.config.http.wait_for_cache': 1,
     'proxy.config.config_update_interval_ms': 1,
 
 })
@@ -53,8 +52,7 @@
 tr.Processes.Default.Command = 'curl "http://127.0.0.1:{0}/default/cache/10/{1}" -H "x-debug: x-cache,x-cache-key,via,x-cache-generation" --verbose'.format(
     ts.Variables.port, objectid)
 tr.Processes.Default.ReturnCode = 0
-# time delay as proxy.config.http.wait_for_cache could be broken
-tr.Processes.Default.StartBefore(Test.Processes.ts, ready=2)
+tr.Processes.Default.StartBefore(Test.Processes.ts)
 tr.Processes.Default.Streams.All = "gold/miss_default-1.gold"
 
 # Same URL in generation 1 is a MISS.

tests/gold_tests/cache/disjoint-wait-for-cache.test.py

@@ -27,7 +27,8 @@
 # Define default ATS
 ts = Test.MakeATSProcess("ts")
 
-# setup some config file for this server
+# Setup some config file for this server. Note that setting wait_for_cache to 3
+# will intentionally override the value set in MakeATSProcess.
 ts.Disk.records_config.update({
     'proxy.config.body_factory.enable_customizations': 3,  # enable domain specific body factory
     'proxy.config.http.cache.generation': -1,  # Start with cache turned off

tests/gold_tests/chunked_encoding/chunked_encoding.test.py

@@ -104,7 +104,6 @@
 tr.Processes.Default.Command = 'curl --http1.1 --proxy 127.0.0.1:{0} http://www.example.com  --verbose'.format(
     ts.Variables.port)
 tr.Processes.Default.ReturnCode = 0
-# time delay as proxy.config.http.wait_for_cache could be broken
 tr.Processes.Default.StartBefore(server)
 tr.Processes.Default.StartBefore(server2)
 tr.Processes.Default.StartBefore(server3)

tests/gold_tests/continuations/double.test.py

@@ -23,8 +23,8 @@
 '''
 
 Test.ContinueOnFail = True
-# Define default ATS
-ts = Test.MakeATSProcess("ts", select_ports=True, command="traffic_manager")
+# Define default ATS. Disable the cache to simplify the test.
+ts = Test.MakeATSProcess("ts", select_ports=True, command="traffic_manager", enable_cache=False)
 server = Test.MakeOriginServer("server")
 
 Test.testName = ""
@@ -74,7 +74,6 @@
 # Execution order is: ts/server, ps(curl cmds), Default Process.
 tr.Processes.Default.StartBefore(
     server, ready=When.PortOpen(server.Variables.Port))
-# Adds a delay once the ts port is ready. This is because we cannot test the ts state.
 tr.Processes.Default.StartBefore(Test.Processes.ts)
 ts.StartAfter(*ps)
 server.StartAfter(*ps)

tests/gold_tests/continuations/double_h2.test.py

@@ -25,8 +25,8 @@
     Condition.HasCurlFeature('http2')
 )
 Test.ContinueOnFail = True
-# Define default ATS
-ts = Test.MakeATSProcess("ts", select_ports=True, enable_tls=True, command="traffic_manager")
+# Define default ATS. Disable the cache to simplify the test.
+ts = Test.MakeATSProcess("ts", select_ports=True, enable_tls=True, command="traffic_manager", enable_cache=False)
 server = Test.MakeOriginServer("server")
 server2 = Test.MakeOriginServer("server2")
 
@@ -57,7 +57,6 @@
     'proxy.config.diags.debug.tags': 'continuations_verify',
     'proxy.config.ssl.server.cert.path': '{0}'.format(ts.Variables.SSLDir),
     'proxy.config.ssl.server.private_key.path': '{0}'.format(ts.Variables.SSLDir),
-    'proxy.config.http.cache.http': 0,  # disable cache to simply the test.
     'proxy.config.cache.enable_read_while_writer': 0,
     'proxy.config.ssl.client.verify.server': 0,
     'proxy.config.ssl.server.cipher_suite': 'ECDHE-RSA-AES128-GCM-SHA256:ECDHE-RSA-AES256-GCM-SHA384:ECDHE-RSA-AES128-SHA256:ECDHE-RSA-AES256-SHA384:AES128-GCM-SHA256:AES256-GCM-SHA384:ECDHE-RSA-RC4-SHA:ECDHE-RSA-AES128-SHA:ECDHE-RSA-AES256-SHA:RC4-SHA:RC4-MD5:AES128-SHA:AES256-SHA:DES-CBC3-SHA!SRP:!DSS:!PSK:!aNULL:!eNULL:!SSLv2',